Bug 1672537

Summary: Run ovirt-ansible-manageiq twice, without removing the manageiq, runs over the v2_key
Product: Red Hat Enterprise Virtualization Manager Reporter: Ilanit Stein <istein>
Component: ovirt-ansible-rolesAssignee: Ondra Machacek <omachace>
Status: CLOSED ERRATA QA Contact: Petr Kubica <pkubica>
Severity: high Docs Contact:
Priority: medium    
Version: 4.2.8CC: abellott, dmetzger, fdupont, istein, jrafanie, lleistne, mperina, obarenbo
Target Milestone: ovirt-4.3.4Keywords: Reopened, ZStream
Target Release: 4.3.1Flags: istein: needinfo+
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: ovirt-ansible-manageiq-1.1.14 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2019-06-20 14:48:22 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: Bug
oVirt Team: Infra RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Ilanit Stein 2019-02-05 09:46:03 UTC
Description of problem:
For a CFME that is connected to a VMware, and RHV Scale,
Rails console fails as follows:

[root@cloudforms vmdb]# rails console 
/opt/rh/cfme-gemset/bundler/gems/cfme-gems-pending-71d6e5aabd0b/lib/gems/pending/util/miq-password.rb:40:in `rescue in decrypt': can not decrypt v2_key encrypted string (MiqPassword::MiqPasswordError)
        from /opt/rh/cfme-gemset/bundler/gems/cfme-gems-pending-71d6e5aabd0b/lib/gems/pending/util/miq-password.rb:37:in `decrypt'
        from /opt/rh/cfme-gemset/bundler/gems/cfme-gems-pending-71d6e5aabd0b/lib/gems/pending/util/miq-password.rb:69:in `decrypt'
        from /opt/rh/cfme-gemset/bundler/gems/cfme-gems-pending-71d6e5aabd0b/lib/gems/pending/util/miq-password.rb:94:in `try_decrypt'
        from /var/www/miq/vmdb/lib/vmdb/settings_walker.rb:56:in `block in decrypt_passwords!'
        from /var/www/miq/vmdb/lib/vmdb/settings_walker.rb:41:in `block in walk_passwords'
        from /var/www/miq/vmdb/lib/vmdb/settings_walker.rb:22:in `block in walk'
        from /var/www/miq/vmdb/lib/vmdb/settings_walker.rb:19:in `each'
        from /var/www/miq/vmdb/lib/vmdb/settings_walker.rb:19:in `walk'
        from /var/www/miq/vmdb/lib/vmdb/settings.rb:47:in `walk'
        from /var/www/miq/vmdb/lib/vmdb/settings_walker.rb:26:in `block in walk'
        from /var/www/miq/vmdb/lib/vmdb/settings_walker.rb:19:in `each'
        from /var/www/miq/vmdb/lib/vmdb/settings_walker.rb:19:in `walk'
        from /var/www/miq/vmdb/lib/vmdb/settings.rb:47:in `walk'
        from /var/www/miq/vmdb/lib/vmdb/settings_walker.rb:40:in `walk_passwords'
        from /var/www/miq/vmdb/lib/vmdb/settings_walker.rb:56:in `decrypt_passwords!'
        from /var/www/miq/vmdb/lib/patches/database_configuration_patch.rb:30:in `database_configuration'
        from /opt/rh/cfme-gemset/gems/activerecord-5.0.7.1/lib/active_record/railtie.rb:122:in `block (2 levels) in <class:Railtie>'
        from /opt/rh/cfme-gemset/gems/activesupport-5.0.7.1/lib/active_support/lazy_load_hooks.rb:69:in `instance_eval'
        from /opt/rh/cfme-gemset/gems/activesupport-5.0.7.1/lib/active_support/lazy_load_hooks.rb:69:in `block in execute_hook'
        from /opt/rh/cfme-gemset/gems/activesupport-5.0.7.1/lib/active_support/lazy_load_hooks.rb:60:in `with_execution_control'
        from /opt/rh/cfme-gemset/gems/activesupport-5.0.7.1/lib/active_support/lazy_load_hooks.rb:65:in `execute_hook'
        from /opt/rh/cfme-gemset/gems/activesupport-5.0.7.1/lib/active_support/lazy_load_hooks.rb:41:in `block in on_load'
        from /opt/rh/cfme-gemset/gems/activesupport-5.0.7.1/lib/active_support/lazy_load_hooks.rb:40:in `each'
        from /opt/rh/cfme-gemset/gems/activesupport-5.0.7.1/lib/active_support/lazy_load_hooks.rb:40:in `on_load'
        from /opt/rh/cfme-gemset/gems/activerecord-5.0.7.1/lib/active_record/railtie.rb:121:in `block in <class:Railtie>'
        from /opt/rh/cfme-gemset/gems/railties-5.0.7.1/lib/rails/initializable.rb:30:in `instance_exec'
        from /opt/rh/cfme-gemset/gems/railties-5.0.7.1/lib/rails/initializable.rb:30:in `run'
        from /opt/rh/cfme-gemset/gems/railties-5.0.7.1/lib/rails/initializable.rb:55:in `block in run_initializers'
        from /usr/share/ruby/tsort.rb:228:in `block in tsort_each'
        from /usr/share/ruby/tsort.rb:350:in `block (2 levels) in each_strongly_connected_component'
        from /usr/share/ruby/tsort.rb:431:in `each_strongly_connected_component_from'
        from /usr/share/ruby/tsort.rb:349:in `block in each_strongly_connected_component'
        from /usr/share/ruby/tsort.rb:347:in `each'
        from /usr/share/ruby/tsort.rb:347:in `call'
        from /usr/share/ruby/tsort.rb:347:in `each_strongly_connected_component'
        from /usr/share/ruby/tsort.rb:226:in `tsort_each'
        from /usr/share/ruby/tsort.rb:205:in `tsort_each'
        from /opt/rh/cfme-gemset/gems/railties-5.0.7.1/lib/rails/initializable.rb:54:in `run_initializers'
        from /opt/rh/cfme-gemset/gems/railties-5.0.7.1/lib/rails/application.rb:352:in `initialize!'
        from /opt/rh/cfme-gemset/gems/railties-5.0.7.1/lib/rails/railtie.rb:193:in `public_send'
        from /opt/rh/cfme-gemset/gems/railties-5.0.7.1/lib/rails/railtie.rb:193:in `method_missing'
        from /var/www/miq/vmdb/config/environment.rb:5:in `<top (required)>'
        from /opt/rh/cfme-gemset/gems/activesupport-5.0.7.1/lib/active_support/dependencies.rb:293:in `require'
        from /opt/rh/cfme-gemset/gems/activesupport-5.0.7.1/lib/active_support/dependencies.rb:293:in `block in require'
        from /opt/rh/cfme-gemset/gems/activesupport-5.0.7.1/lib/active_support/dependencies.rb:259:in `load_dependency'
        from /opt/rh/cfme-gemset/gems/activesupport-5.0.7.1/lib/active_support/dependencies.rb:293:in `require'
        from /opt/rh/cfme-gemset/gems/railties-5.0.7.1/lib/rails/application.rb:328:in `require_environment!'
        from /opt/rh/cfme-gemset/gems/railties-5.0.7.1/lib/rails/commands/commands_tasks.rb:157:in `require_application_and_environment!'
        from /opt/rh/cfme-gemset/gems/railties-5.0.7.1/lib/rails/commands/commands_tasks.rb:77:in `console'
        from /opt/rh/cfme-gemset/gems/railties-5.0.7.1/lib/rails/commands/commands_tasks.rb:49:in `run_command!'
        from /opt/rh/cfme-gemset/gems/railties-5.0.7.1/lib/rails/commands.rb:18:in `<top (required)>'
        from bin/rails:4:in `require'
        from bin/rails:4:in `<main>'


Version-Release number of selected component (if applicable):
CFME-5.10.0.33/RHV-4.2.8-4
(It also occurred with CFME-5.10.0.32/RHV-4.2.8-4 when I tested it 2 weeks ago).

How reproducible:
Not sure what is the flow that makes this happen.
On the previous time it happen, I installed the CFME appliance from scratch.

Comment 2 Ilanit Stein 2019-02-05 09:55:14 UTC
* This bug might be related to v2v (VMware to RHV), since this CFME was used for running it (successfully).

* Tried to restart evmserverd service, and now I can't connect to the CFME UI:

[root@cloudforms vmdb]# systemctl restart evmserverd
Job for evmserverd.service failed because the control process exited with error code. See "systemctl status evmserverd.service" and "journalctl -xe" for details.

[root@cloudforms log]# systemctl status evmserverd.service
● evmserverd.service - EVM server daemon
   Loaded: loaded (/usr/lib/systemd/system/evmserverd.service; enabled; vendor preset: disabled)
   Active: activating (start) since Tue 2019-02-05 04:49:02 EST; 914ms ago
 Main PID: 15432 (code=exited, status=0/SUCCESS);         : 35815 (evmserver.sh)
   CGroup: /system.slice/evmserverd.service
           ├─17243 /usr/lib64/erlang/erts-8.3.5.4/bin/epmd -daemon
           ├─35815 /bin/bash /bin/evmserver.sh start
           └─35820 /opt/rh/cfme-gemset/bin/rake evm:start

Feb 05 04:49:02 cloudforms.rhev.openstack.engineering.redhat.com systemd[1]: Starting EVM server daemon...
[root@cloudforms log]# journalctl -xe
Feb 05 04:49:27 cloudforms.rhev.openstack.engineering.redhat.com sh[35860]: /opt/rh/cfme-gemset/gems/activesupport-5.0.7.1/lib/active_support/de
Feb 05 04:49:27 cloudforms.rhev.openstack.engineering.redhat.com sh[35860]: /opt/rh/cfme-gemset/gems/activesupport-5.0.7.1/lib/active_support/de
Feb 05 04:49:27 cloudforms.rhev.openstack.engineering.redhat.com sh[35860]: /opt/rh/cfme-gemset/gems/activesupport-5.0.7.1/lib/active_support/de
Feb 05 04:49:27 cloudforms.rhev.openstack.engineering.redhat.com sh[35860]: /opt/rh/cfme-gemset/gems/activesupport-5.0.7.1/lib/active_support/de
Feb 05 04:49:27 cloudforms.rhev.openstack.engineering.redhat.com sh[35860]: /opt/rh/cfme-gemset/gems/activesupport-5.0.7.1/lib/active_support/de
Feb 05 04:49:27 cloudforms.rhev.openstack.engineering.redhat.com sh[35860]: /opt/rh/cfme-gemset/gems/railties-5.0.7.1/lib/rails/application.rb:3
Feb 05 04:49:27 cloudforms.rhev.openstack.engineering.redhat.com sh[35860]: /opt/rh/cfme-gemset/gems/railties-5.0.7.1/lib/rails/application.rb:4
Feb 05 04:49:27 cloudforms.rhev.openstack.engineering.redhat.com sh[35860]: /opt/rh/cfme-gemset/gems/rake-12.3.2/exe/rake:27:in `<top (required)
Feb 05 04:49:27 cloudforms.rhev.openstack.engineering.redhat.com sh[35860]: /opt/rh/cfme-gemset/gems/bundler-1.15.4/lib/bundler/cli/exec.rb:74:i
Feb 05 04:49:27 cloudforms.rhev.openstack.engineering.redhat.com sh[35860]: /opt/rh/cfme-gemset/gems/bundler-1.15.4/lib/bundler/cli/exec.rb:74:i
Feb 05 04:49:27 cloudforms.rhev.openstack.engineering.redhat.com sh[35860]: /opt/rh/cfme-gemset/gems/bundler-1.15.4/lib/bundler/cli/exec.rb:27:i
Feb 05 04:49:27 cloudforms.rhev.openstack.engineering.redhat.com sh[35860]: /opt/rh/cfme-gemset/gems/bundler-1.15.4/lib/bundler/cli.rb:362:in `e
Feb 05 04:49:27 cloudforms.rhev.openstack.engineering.redhat.com sh[35860]: /opt/rh/cfme-gemset/gems/bundler-1.15.4/lib/bundler/vendor/thor/lib/
Feb 05 04:49:27 cloudforms.rhev.openstack.engineering.redhat.com sh[35860]: /opt/rh/cfme-gemset/gems/bundler-1.15.4/lib/bundler/vendor/thor/lib/
Feb 05 04:49:27 cloudforms.rhev.openstack.engineering.redhat.com sh[35860]: /opt/rh/cfme-gemset/gems/bundler-1.15.4/lib/bundler/vendor/thor/lib/
Feb 05 04:49:27 cloudforms.rhev.openstack.engineering.redhat.com sh[35860]: /opt/rh/cfme-gemset/gems/bundler-1.15.4/lib/bundler/cli.rb:22:in `di
Feb 05 04:49:27 cloudforms.rhev.openstack.engineering.redhat.com sh[35860]: /opt/rh/cfme-gemset/gems/bundler-1.15.4/lib/bundler/vendor/thor/lib/
Feb 05 04:49:27 cloudforms.rhev.openstack.engineering.redhat.com sh[35860]: /opt/rh/cfme-gemset/gems/bundler-1.15.4/lib/bundler/cli.rb:13:in `st
Feb 05 04:49:27 cloudforms.rhev.openstack.engineering.redhat.com sh[35860]: /opt/rh/cfme-gemset/gems/bundler-1.15.4/exe/bundle:30:in `block in <
Feb 05 04:49:27 cloudforms.rhev.openstack.engineering.redhat.com sh[35860]: /opt/rh/cfme-gemset/gems/bundler-1.15.4/lib/bundler/friendly_errors.
Feb 05 04:49:27 cloudforms.rhev.openstack.engineering.redhat.com systemd[1]: evmserverd.service: control process exited, code=exited status=1
Feb 05 04:49:27 cloudforms.rhev.openstack.engineering.redhat.com sh[35860]: /opt/rh/cfme-gemset/gems/bundler-1.15.4/exe/bundle:22:in `<top (requ
Feb 05 04:49:27 cloudforms.rhev.openstack.engineering.redhat.com sh[35860]: /opt/rh/cfme-gemset/bin/bundle:23:in `load'
Feb 05 04:49:27 cloudforms.rhev.openstack.engineering.redhat.com sh[35860]: /opt/rh/cfme-gemset/bin/bundle:23:in `<main>'
Feb 05 04:49:27 cloudforms.rhev.openstack.engineering.redhat.com sh[35860]: Tasks: TOP => evm:start => environment
Feb 05 04:49:27 cloudforms.rhev.openstack.engineering.redhat.com sh[35860]: (See full trace by running task with --trace)
Feb 05 04:49:27 cloudforms.rhev.openstack.engineering.redhat.com systemd[1]: Failed to start EVM server daemon.
-- Subject: Unit evmserverd.service has failed
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- Unit evmserverd.service has failed.
-- 
-- The result is failed.
Feb 05 04:49:27 cloudforms.rhev.openstack.engineering.redhat.com systemd[1]: Unit evmserverd.service entered failed state.
Feb 05 04:49:27 cloudforms.rhev.openstack.engineering.redhat.com systemd[1]: evmserverd.service failed.
Feb 05 04:49:27 cloudforms.rhev.openstack.engineering.redhat.com systemd[1]: evmserverd.service holdoff time over, scheduling restart.
Feb 05 04:49:27 cloudforms.rhev.openstack.engineering.redhat.com systemd[1]: Stopped EVM server daemon.
-- Subject: Unit evmserverd.service has finished shutting down
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- Unit evmserverd.service has finished shutting down.
Feb 05 04:49:27 cloudforms.rhev.openstack.engineering.redhat.com systemd[1]: Starting EVM server daemon...
-- Subject: Unit evmserverd.service has begun start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- Unit evmserverd.service has begun starting up.

Comment 3 Joe Rafaniello 2019-02-05 20:25:44 UTC
Ilanit, this error usually happens when you restore a database with passwords but don't copy over the v2_key from the vmdb/certs directory.

I'm not sure what was the process followed to create this bug.  Can you review the v2_key to see if that could be the problem?

Comment 4 Ilanit Stein 2019-02-06 13:05:51 UTC
Thanks Joe.

Database restore was not done.
I don't know what caused this problem.
but there are 2 things bothering me:
1. I didn't do anything that is not considered as normal usage of the system.
2. I encountered it more than once, on different CFME versions (also latest)

How can I review the v2_key please?

Comment 5 Joe Rafaniello 2019-02-07 15:05:01 UTC
Hi Ilanit.

The error I'm talking about is:
can not decrypt v2_key encrypted string (MiqPassword::MiqPasswordError)

If you're getting that error and the evmserverd process will not start, you need to check your v2_key.  If you are restoring a db or connecting to another db, you need to use the v2_key from the system that created the passwords.

The v2_key is  an encryption key found in vmdb/certs/v2_key.  We generate this on new installations and passwords that are stored in the database are encrypted using this key.  Therefore, you must copy the v2_key when you export/restore a database.

Are you using a brand new database? Is it possible someone connected to your database and stored a password using a different key?

Comment 6 Ilanit Stein 2019-02-10 07:37:24 UTC
Joe,

Thanks for explaining that.

I am not aware of any db connection trials.

The CFME with the v2_key issue no longer exist.

I will update the bug, once I'll hit it again.

Comment 7 Joe Rafaniello 2019-02-11 15:59:52 UTC
Closing for now, let's reopen when we have more information.

Comment 8 Ilanit Stein 2019-02-12 07:29:17 UTC
I had this failure again.

I think this is happening after I run oVirt.manageiq CFME deploy on RHV, without removing the CFME VM first.
I suspect that something done in the database init part may cause this.

Normally, in testing the CFME is deployed each time from new.
But in this case it is not.

Reopenning this bug, as it is reproducing quite often, and we now have some direction.

I can provide env if required.

Comment 9 Ilanit Stein 2019-02-12 10:17:09 UTC
Now I am certain that this is happening when I run Ansible automation for CFME deploy, without removing the CFME VM.
The problem can be reproduced.

Comment 10 Ilanit Stein 2019-02-12 10:42:45 UTC
This is the step in the oVirt.manageiq role that causes the failure:

TASK [oVirt.manageiq : Initialize CloudForms] **********************************
changed: [localhost -> 10.12.69.26]

Comment 11 Joe Rafaniello 2019-02-12 13:11:53 UTC
> after I run oVirt.manageiq CFME deploy on RHV, without removing the CFME VM first

Thanks Ilanit.  I'm unfamiliar with the RHV tems you're using here.  Can explain what you mean by CFME deploy on RHV without removing the CFME VM first?  Are you importing the downloaded appliance image onto RHV storage, creating a vm from it and starting it? Or are you using some automation to deploy the CFME?  If so, where is this automation?  Where is the source code for the ansible/automate scripts that deploy this? What do you mean by removing the CFME Vm first?  Is this new appliance being deployed to connect to the existing CFME vm's database?  Can you compare the hostname/ip addresses of the two CFME appliances and compare them to their config/database.yml files?  

Thanks!

Comment 12 Ilanit Stein 2019-02-13 08:14:47 UTC
This is the ansible role I use:

Ansible role to create ManageIQ or CloudForms virtual machine from qcow image on RHV": 
https://github.com/oVirt/ovirt-ansible-manageiq
(It is delivered within RHV).

This is the flow that generates the bug:

1. Run this role. As a result a new CFME VM is created on RHV.
   It's database is initiated, and rails console works OK.
2. Do not delete the CFME VM.
3. Run the role again.
   The rails console fail on v2_key error.
 
 
We run automation for v2v flow testing, and the CFME VM deploy is the first step.
If we run this flow for the second time, without removing the CFME VM beforehand,
it will create the v2_key error. 

I shall send the failing CFME by email.

Comment 13 Joe Rafaniello 2019-02-13 12:24:51 UTC
I'm really unfamiliar with ovirt-ansible-manageiq.  Can you try something?

1) After your step 1, copy off the vmdb/certs/v2_key
2) After your step 3, verify if you get a v2_key decrypt error.  If you do, backup your existing vmdb/certs/v2_key.  Then, copy over the v2_key from step 1 and see if that v2_key encounters the same v2_key error or if it works.

If it works in step 2, then the initialization of the ovirt-ansible-manageiq appliance db/v2_key has a bug.  I'm not sure how to get that fixed.  I can reassign it to a different group perhaps.

Comment 14 Ilanit Stein 2019-02-14 08:17:18 UTC
Thanks Joe,

Step 2 works.

So there is a bug in the initialization of the ovirt-ansible-manageiq appliance db/v2_key.
Comment #12 describe the bug flow.
Comment #13 describe the bug work around. 

Moving bug to Ondra - the Ansible playbook owner.

Comment 16 Martin Perina 2019-03-08 14:01:26 UTC
Ilanit, could you please describe your goal? Why do want to deploy more ManageIQ/CFME setups within single oVirt/RHV setup?

The main purpose of ovirt.manageiq role is to deploy ManageIQ/CFME as a VM within oVirt/RHV setup and configure oVirt/RHV provider within ManageIQ/CFME VM to be able to communicate with oVirt/RHV setup.

Comment 17 Ilanit Stein 2019-03-10 06:48:48 UTC
Martin,

This is not about deploy more CFME VMs on same RHV.

The bug is that if the oVirt.manageiq role is run twice, 
On the first run it 1.deploys a CFME VM on RHV, 2.configure it data base, and then 3. adds this CFME as a provider to the RHV.
On a second run, in case the CFME VM was not removed, it SHOULD identify all these 3 steps, were already run, and skips them.
however, what it is actually doing is initializing the data base, in such way that the v2v_key changes.
This causes the Rails Console run fail, as it cannot access the database.

A second run of the role should not harm the database access.

In IMS testing (RHV->VMware), 
We have a flow, that deploys CFME on RHV (using ovirt.manageiq role), and then does thing on CFME.
To save run time, the flow was run more than once, __without__ removing the CFME VM, in between the runs.
But then, when I needed Rails console access, it failed.

Comment 21 Petr Kubica 2019-05-28 11:40:28 UTC
Verified in ovirt-ansible-manageiq-1.1.15-0.1.master.20190515131718.el7.noarch with ManageIQ
ansible-2.8.0-0.5.b1.el7ae.noarch

Comment 23 errata-xmlrpc 2019-06-20 14:48:22 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/RHEA-2019:1564