Bug 1729166 - [Embedded Ansible] Getting error "[StandardError]: Embedded ansible is disabled" in evm.log
Summary: [Embedded Ansible] Getting error "[StandardError]: Embedded ansible is disabl...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat CloudForms Management Engine
Classification: Red Hat
Component: Appliance
Version: 5.10.7
Hardware: Unspecified
OS: Unspecified
medium
medium
Target Milestone: GA
: 5.10.12
Assignee: Joe Rafaniello
QA Contact: Satyajit Bulage
Red Hat CloudForms Documentation
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2019-07-11 13:28 UTC by Satyajit Bulage
Modified: 2019-11-06 08:58 UTC (History)
7 users (show)

Fixed In Version: 5.10.12.0
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2019-11-06 08:58:33 UTC
Category: ---
Cloudforms Team: CFME Core
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)
evm.log after disabling role. (3.52 KB, application/x-xz)
2019-07-11 13:28 UTC, Satyajit Bulage
no flags Details

Description Satyajit Bulage 2019-07-11 13:28:39 UTC
Created attachment 1589510 [details]
evm.log after disabling role.

Description of problem: Enable Embedded Ansible server role. Add repository, create and order service. Disable Embedded Ansible server role.

OR

Simply enable role wait for notification. Disable role. Watch evm.log for this string: [StandardError]: Embedded ansible is disabled


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


How reproducible: 100%


Steps to Reproduce:
1.
2.
3.

Actual results: [StandardError]: Embedded ansible is disabled


Expected results: There should be error present after role is disabled.


Additional info:

Works in previous version of 5.10.x
See Attached evm.log

Comment 4 Joe Rafaniello 2019-07-11 14:50:14 UTC
Hi Satyajit,

Can you help me understand how it "worked" in 5.10.x?  What do you mean "There should be error present after role is disabled".  Where is the error in 5.10.x?  Can you send me a screenshot or explain what you mean?


"Expected results: There should be error present after role is disabled.


Additional info:

Works in previous version of 5.10.x
See Attached evm.log"

Comment 6 Satyajit Bulage 2019-07-11 14:58:12 UTC
(In reply to Joe Rafaniello from comment #4)
> Hi Satyajit,
> 
> Can you help me understand how it "worked" in 5.10.x?  What do you mean
> "There should be error present after role is disabled".  Where is the error
> in 5.10.x?  Can you send me a screenshot or explain what you mean?
> 
> 
> "Expected results: There should be error present after role is disabled.

Typo :(

"Expected results: There should not be error present after role is disabled.

> 
> 
> Additional info:
> 
> Works in previous version of 5.10.x
> See Attached evm.log"

Comment 7 Joe Rafaniello 2019-07-11 15:16:30 UTC
Do you have an example logs with 5.10.x?  Things to check for:

ems_inventory role is enabled in 5.10.x
ems_refresh is queued for embedded ansible (it's possible we avoid queueing if the embedded ansible role is disabled, therefore it could be a timing issue (queue it before the role is disabled))

What do we want to solve here?
1) Don't queue refreshes for a disabled provider
2) Don't log a backtrace for a refresh of a disabled provider
3) Exit the refresh worker for a disabled provider

Note, we don't pick up role changes instantly so there's always going to be some delay between the role being disabled and workers exiting, queue items no longer being added, etc.

Please advise what you we want to solve here.

Also, can you provide the full evm log on 5.11.x.  I would like to see how queueing and exiting of the worker performed in 5.11.x

Thanks!

Comment 9 Joe Rafaniello 2019-07-11 15:56:49 UTC
Please provide the full log so I can see which of the items below are a problem in 5.11.x.

1) Don't queue refreshes for a disabled provider
2) Don't log a backtrace for a refresh of a disabled provider / continually refresh
3) Exit the refresh worker for a disabled provider
4) Something else...


I honestly still don't know what the regression is here.
Please send me a link to a 5.10.x appliance/logs where this doesn't happen.

I'm leaning towards treating this as an enhancement/bugfix without a specific regression that can be identified.

Comment 10 Joe Rafaniello 2019-07-11 16:04:58 UTC
Looking at the 197.111 reproducer environment on 5.10.7.0, I'm seeing the same error:

[root@dhcp-8-197-111 vmdb]# grep -A 10  "StandardError" log/evm.log
[----] E, [2019-07-11T09:16:37.433726 #37934:97af54] ERROR -- : [StandardError]: Embedded ansible is disabled  Method:[block (2 levels) in <class:LogProxy>]
[----] E, [2019-07-11T09:16:37.433921 #37934:97af54] ERROR -- : /var/www/miq/vmdb/app/models/manageiq/providers/embedded_ansible/provider.rb:14:in `raw_connect'
/opt/rh/cfme-gemset/bundler/gems/cfme-providers-ansible_tower-719c9e2619ed/app/models/manageiq/providers/ansible_tower/shared/provider.rb:41:in `connect'
/var/www/miq/vmdb/app/models/provider.rb:56:in `with_provider_connection'
/opt/rh/cfme-gemset/bundler/gems/cfme-providers-ansible_tower-719c9e2619ed/app/models/manageiq/providers/ansible_tower/shared/automation_manager.rb:5:in `with_provider_connection'
/opt/rh/cfme-gemset/bundler/gems/cfme-providers-ansible_tower-719c9e2619ed/app/models/manageiq/providers/ansible_tower/shared/automation_manager/refresher.rb:3:in `collect_inventory_for_targets'
/var/www/miq/vmdb/app/models/manageiq/providers/base_manager/refresher.rb:97:in `block in refresh_targets_for_ems'
/opt/rh/cfme-gemset/bundler/gems/cfme-gems-pending-7300bf53e177/lib/gems/pending/util/extensions/miq-benchmark.rb:11:in `realtime_store'
/opt/rh/cfme-gemset/bundler/gems/cfme-gems-pending-7300bf53e177/lib/gems/pending/util/extensions/miq-benchmark.rb:28:in `realtime_block'
/var/www/miq/vmdb/app/models/manageiq/providers/base_manager/refresher.rb:96:in `refresh_targets_for_ems'
/var/www/miq/vmdb/app/models/manageiq/providers/base_manager/refresher.rb:41:in `block (2 levels) in refresh'
--
[----] E, [2019-07-11T09:31:28.676589 #37934:97af54] ERROR -- : [StandardError]: Embedded ansible is disabled  Method:[block (2 levels) in <class:LogProxy>]
[----] E, [2019-07-11T09:31:28.676807 #37934:97af54] ERROR -- : /var/www/miq/vmdb/app/models/manageiq/providers/embedded_ansible/provider.rb:14:in `raw_connect'
/opt/rh/cfme-gemset/bundler/gems/cfme-providers-ansible_tower-719c9e2619ed/app/models/manageiq/providers/ansible_tower/shared/provider.rb:41:in `connect'
/var/www/miq/vmdb/app/models/provider.rb:56:in `with_provider_connection'
/opt/rh/cfme-gemset/bundler/gems/cfme-providers-ansible_tower-719c9e2619ed/app/models/manageiq/providers/ansible_tower/shared/automation_manager.rb:5:in `with_provider_connection'
/opt/rh/cfme-gemset/bundler/gems/cfme-providers-ansible_tower-719c9e2619ed/app/models/manageiq/providers/ansible_tower/shared/automation_manager/refresher.rb:3:in `collect_inventory_for_targets'
/var/www/miq/vmdb/app/models/manageiq/providers/base_manager/refresher.rb:97:in `block in refresh_targets_for_ems'
/opt/rh/cfme-gemset/bundler/gems/cfme-gems-pending-7300bf53e177/lib/gems/pending/util/extensions/miq-benchmark.rb:11:in `realtime_store'
/opt/rh/cfme-gemset/bundler/gems/cfme-gems-pending-7300bf53e177/lib/gems/pending/util/extensions/miq-benchmark.rb:28:in `realtime_block'
/var/www/miq/vmdb/app/models/manageiq/providers/base_manager/refresher.rb:96:in `refresh_targets_for_ems'
/var/www/miq/vmdb/app/models/manageiq/providers/base_manager/refresher.rb:41:in `block (2 levels) in refresh'
--
[----] E, [2019-07-11T09:46:30.126763 #37934:97af54] ERROR -- : [StandardError]: Embedded ansible is disabled  Method:[block (2 levels) in <class:LogProxy>]
[----] E, [2019-07-11T09:46:30.126936 #37934:97af54] ERROR -- : /var/www/miq/vmdb/app/models/manageiq/providers/embedded_ansible/provider.rb:14:in `raw_connect'
/opt/rh/cfme-gemset/bundler/gems/cfme-providers-ansible_tower-719c9e2619ed/app/models/manageiq/providers/ansible_tower/shared/provider.rb:41:in `connect'
/var/www/miq/vmdb/app/models/provider.rb:56:in `with_provider_connection'
/opt/rh/cfme-gemset/bundler/gems/cfme-providers-ansible_tower-719c9e2619ed/app/models/manageiq/providers/ansible_tower/shared/automation_manager.rb:5:in `with_provider_connection'
/opt/rh/cfme-gemset/bundler/gems/cfme-providers-ansible_tower-719c9e2619ed/app/models/manageiq/providers/ansible_tower/shared/automation_manager/refresher.rb:3:in `collect_inventory_for_targets'
/var/www/miq/vmdb/app/models/manageiq/providers/base_manager/refresher.rb:97:in `block in refresh_targets_for_ems'
/opt/rh/cfme-gemset/bundler/gems/cfme-gems-pending-7300bf53e177/lib/gems/pending/util/extensions/miq-benchmark.rb:11:in `realtime_store'
/opt/rh/cfme-gemset/bundler/gems/cfme-gems-pending-7300bf53e177/lib/gems/pending/util/extensions/miq-benchmark.rb:28:in `realtime_block'
/var/www/miq/vmdb/app/models/manageiq/providers/base_manager/refresher.rb:96:in `refresh_targets_for_ems'
/var/www/miq/vmdb/app/models/manageiq/providers/base_manager/refresher.rb:41:in `block (2 levels) in refresh'

Comment 12 dmetzger 2019-07-31 13:17:34 UTC
Please verify if this behavior is the same with 5.11.0

Comment 14 Joe Rafaniello 2019-08-29 20:38:02 UTC
Hi Satyajit,

I have opened a pull request for this issue, please see: https://github.com/ManageIQ/manageiq/pull/19229

Summary:
* error is still printed as ERROR, telling you that you have the role disabled
* the ruby backtrace is no longer printed

Note, this is a 5.10 hammer only fix as 5.11/ivanchuk has the original code removed since we went to ansible runner.

Comment 17 CFME Bot 2019-10-04 17:00:47 UTC
New commit detected on ManageIQ/manageiq/hammer:

https://github.com/ManageIQ/manageiq/commit/1b4010fae6a6a9cb01f45d48069c66a60957f152
commit 1b4010fae6a6a9cb01f45d48069c66a60957f152
Author:     Joe Rafaniello <jrafanie>
AuthorDate: Thu Aug 29 16:28:03 2019 -0400
Commit:     Joe Rafaniello <jrafanie>
CommitDate: Thu Aug 29 16:28:03 2019 -0400

    log_backtrace won't print backtrace for MiqException errors

    See: https://github.com/ManageIQ/manageiq-gems-pending/blob/hammer/lib/gems/pending/util/vmdb-logger.rb#L106

    This will still print as an ERROR level but the backtrace will not be printed to the log as this is a known
    error condition where the backtrace is not needed.
    Fixes: https://bugzilla.redhat.com/show_bug.cgi?id=1729166

    Note, embedded ansible was converted to use runner starting in ivanchuk, therefore this is a hammer only change.

    See: https://github.com/ManageIQ/manageiq/pull/18687

 app/models/manageiq/providers/embedded_ansible/provider.rb | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

Comment 19 Joe Rafaniello 2019-10-09 17:27:13 UTC
I'm not sure what to do about this.

The original location is no longer logging the backtrace, so that part is fixed... but the summary refresh code is still logging the backtrace as it does with all exceptions.  We could teach refresh to not hit this exception by filtering out the embedded ansible providers if the role is disabled but this provider has been removed on master so any changes we make should be minimal as it's a hammer only change.

Comment 22 Satyajit Bulage 2019-10-11 15:13:00 UTC
Considering comment 18, comment 19 and comment 20, Able to see this BZ is fixed and cannot see the failure after disabling Embedded Ansible error in the logs.

Verified Version: 5.10.12.0.20191007204014_0d55c84

Comment 24 errata-xmlrpc 2019-11-06 08:58:33 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2019:3268


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