Bug 1337452

Summary:

upgrade[sat6.1.9 -> Sat6.2 snap12] error while updating satellite packages: Error on on_execution_plan_save event

Product:

Red Hat Satellite

Reporter:

Sachin Ghai <sghai>

Component:

Upgrades

Assignee:

Daniel Lobato Garcia <dlobatog>

Status:

CLOSED WORKSFORME

QA Contact:

Sachin Ghai <sghai>

Severity:

high

Docs Contact:

Priority:

unspecified

Version:

6.2.0

CC:

bbuckingham, inecas, ohadlevy, sghai

Target Milestone:

Unspecified

Keywords:

Reopened, Triaged

Target Release:

Unused

Hardware:

Unspecified

OS:

Unspecified

Whiteboard:

Fixed In Version:

Doc Type:

If docs needed, set a value

Doc Text:

Story Points:

---

Clone Of:

Environment:

Last Closed:

2016-06-09 08:28:13 UTC

Type:

Bug

Regression:

---

Mount Type:

---

Documentation:

---

CRM:

Verified Versions:

Category:

---

oVirt Team:

---

RHEL 7.3 requirements from Atomic Host:

Cloudforms Team:

---

Target Upstream Version:

Embargoed:

Bug Depends On:

Bug Blocks:

1335807

Attachments:

Description	Flags
complete exception	none
foreman-debug logs	none
complete_exception_snap13.txt	none
foreman-debug from recent upgrade with snap13.1	none

Description Sachin Ghai 2016-05-19 09:09:06 UTC

Description of problem:
Following exception raised in production.log while performing "yum update"
to update packages from  sat6.1.9 -> Sat6.2 snap12. Though the log-level seems "warning" but its looks like something went wrong as statement says:  Error on on_execution_plan_save event.

And next line says "| RuntimeError: Circular dependency detected while autoloading constant ForemanTasks::Task::DynflowTask"


Please see the logs below.

==> /var/log/foreman/production.log <==
2016-05-19 04:30:10 [foreman-tasks/dynflow] [W] Error on on_execution_plan_save event
 | RuntimeError: Circular dependency detected while autoloading constant ForemanTasks::Task::DynflowTask
 | /opt/rh/rh-ror41/root/usr/share/gems/gems/activesupport-4.1.5/lib/active_support/dependencies.rb:478:in `load_missing_constant'



Version-Release number of selected component (if applicable):
upgrade[sat6.1.9 -> Sat6.2 snap12]

How reproducible:


Steps to Reproduce:
1. set sat6.2 repo
2. katello-service stop
3. yum update -y

Actual results:
==> /var/log/foreman/production.log <==
2016-05-19 04:30:10 [foreman-tasks/dynflow] [W] Error on on_execution_plan_save event
 | RuntimeError: Circular dependency detected while autoloading constant ForemanTasks::Task::DynflowTask
 | /opt/rh/rh-ror41/root/usr/share/gems/gems/activesupport-4.1.5/lib/active_support/dependencies.rb:478:in `load_missing_constant'


Expected results:
The statement itself includes Error and Runtime error though log level is warning. I'm not sure if that runtime error affects any area in satellite but it may lead a confusion for customers while performing upgrade.

So if its a real issue, we should fix or we should suppress such exceptions, if possible.

Additional info:

Comment 1 Sachin Ghai 2016-05-19 09:10:35 UTC

Created attachment 1159324 [details]
complete exception

Comment 2 Sachin Ghai 2016-05-19 09:26:50 UTC

Created attachment 1159330 [details]
foreman-debug logs

Comment 4 Sachin Ghai 2016-05-20 09:33:47 UTC

As dev suggested to perform upgrade including 'yum install satellite -y' before performing 'yum update -y'. So this issue is not reproducible with following steps:

1. Disable sat6.1 repo 
2. Set/enable sat6.2 repo
3. yum install satellite -y
4. yum update -y
5. satellite-installer --scenario satellite --upgrade 

Closing this out and will re-open if come across again with above upgrade steps. thanks

Comment 5 Sachin Ghai 2016-05-26 06:33:23 UTC

Okay, Now instructions are little bit changed as satellite packages installed with yum update -y ( so "yum install satellite -y" not required).

with following steps, this issue is reproducible with upgrade from sat6.1.9 -> 6.2 snap13.1.

2016-05-26 01:11:59 [foreman-tasks/dynflow] [W] Error on on_execution_plan_save event
 | NoMethodError: undefined method `start_at' for #<ForemanTasks::Task::DynflowTask:0x0000000f02d348>
 | /opt/rh/rh-ror41/root/usr/share/gems/gems/activemodel-4.1.5/lib/active_model/attribute_methods.rb:435:in `method_missing'
 | /opt/rh/rh-ror41/root/usr/share/gems/gems/activerecord-4.1.5/lib/active_record/attribute_methods.rb:208:in `method_missing'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.7.14.4/lib/foreman_tasks/dynflow/persistence.rb:29:in `on_execution_plan_save'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.7.14.4/lib/foreman_tasks/dynflow/persistence.rb:14:in `block in save_execution_plan'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.7.14.4/lib/foreman_tasks/dynflow/persistence.rb:12:in `tap'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.7.14.4/lib/foreman_tasks/dynflow/persistence.rb:12:in `save_execution_plan'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.11/lib/dynflow/persistence.rb:49:in `save_execution_plan'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.11/lib/dynflow/execution_plan.rb:335:in `save'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.11/lib/dynflow/execution_plan.rb:182:in `prepare'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.11/lib/dynflow/world.rb:167:in `block in plan'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.11/lib/dynflow/world.rb:166:in `tap'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.11/lib/dynflow/world.rb:166:in `plan'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.11/lib/dynflow/world.rb:142:in `trigger'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.7.14.4/lib/foreman_tasks.rb:18:in `trigger'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.7.14.4/lib/foreman_tasks.rb:24:in `trigger_task'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.7.14.4/lib/foreman_tasks.rb:39:in `sync_task'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.7.14.4/lib/foreman_tasks/triggers.rb:22:in `sync_task'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.0.0.35/app/controllers/katello/api/rhsm/candlepin_proxies_controller.rb:116:in `block in hypervisors_update'

Comment 6 Sachin Ghai 2016-05-26 06:34:23 UTC

Please note that this exception is being raised a bunch of times while running "yum update -y"

Comment 7 Sachin Ghai 2016-05-26 06:44:09 UTC

Steps taken to reproduce:

1. Set sat6.2 repo on existing sat6.1 setup
2. yum update -y

Comment 8 Sachin Ghai 2016-05-26 06:45:41 UTC

Another instance of exception

==> /var/log/foreman/production.log <==
2016-05-26 01:12:00 [app] [I] Started POST "/rhsm/hypervisors?owner=Default_Organization&env=Library" for 10.8.119.1 at 2016-05-26 01:12:00 -0400
2016-05-26 01:12:00 [app] [I] Processing by Katello::Api::Rhsm::CandlepinProxiesController#hypervisors_update as JSON
2016-05-26 01:12:00 [app] [I]   Parameters: {"rhevh2"=>[{"guestId"=>"f4d38b28-b313-4040-9b70-84f4179e9873", "state"=>1, "attributes"=>{"active"=>1, "virtWhoType"=>"rhevm", "hypervisorType"=>"qemu"}}, {"guestId"=>"1428a01b-41a6-4c7b-8fac-d57c942d1507", "state"=>1, "attributes"=>{"active"=>1, "virtWhoType"=>"rhevm", "hypervisorType"=>"qemu"}}, {"guestId"=>"0c87d5eb-90d1-4514-9855-0186c88f374e", "state"=>1, "attributes"=>{"active"=>1, "virtWhoType"=>"rhevm", "hypervisorType"=>"qemu"}}, {"guestId"=>"73b130fc-07a7-4502-86e8-11b06427c43f", "state"=>1, "attributes"=>{"active"=>1, "virtWhoType"=>"rhevm", "hypervisorType"=>"qemu"}}], "owner"=>"Default_Organization", "env"=>"Library"}
2016-05-26 01:12:00 [app] [I] Expire fragment views/tabs_and_title_records-3 (0.2ms)
2016-05-26 01:12:00 [katello/cp_proxy] [I] Authorized user admin(Admin User)
2016-05-26 01:12:00 [foreman-tasks/dynflow] [W] Error on on_execution_plan_save event
 | NoMethodError: undefined method `start_at' for #<ForemanTasks::Task::DynflowTask:0x00000010543b60>
 | /opt/rh/rh-ror41/root/usr/share/gems/gems/activemodel-4.1.5/lib/active_model/attribute_methods.rb:435:in `method_missing'
 | /opt/rh/rh-ror41/root/usr/share/gems/gems/activerecord-4.1.5/lib/active_record/attribute_methods.rb:208:in `method_missing'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.7.14.4/lib/foreman_tasks/dynflow/persistence.rb:29:in `on_execution_plan_save'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.7.14.4/lib/foreman_tasks/dynflow/persistence.rb:14:in `block in save_execution_plan'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.7.14.4/lib/foreman_tasks/dynflow/persistence.rb:12:in `tap'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.7.14.4/lib/foreman_tasks/dynflow/persistence.rb:12:in `save_execution_plan'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.11/lib/dynflow/persistence.rb:49:in `save_execution_plan'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.11/lib/dynflow/execution_plan.rb:335:in `save'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.11/lib/dynflow/execution_plan.rb:182:in `prepare'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.11/lib/dynflow/world.rb:167:in `block in plan'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.11/lib/dynflow/world.rb:166:in `tap'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.11/lib/dynflow/world.rb:166:in `plan'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.11/lib/dynflow/world.rb:142:in `trigger'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.7.14.4/lib/foreman_tasks.rb:18:in `trigger'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.7.14.4/lib/foreman_tasks.rb:24:in `trigger_task'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.7.14.4/lib/foreman_tasks.rb:39:in `sync_task'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.7.14.4/lib/foreman_tasks/triggers.rb:22:in `sync_task'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.0.0.35/app/controllers/katello/api/rhsm/candlepin_proxies_controller.rb:116:in `block in hypervisors_update'

Comment 9 Sachin Ghai 2016-05-26 07:19:52 UTC

Another instance of error:

2016-05-26 01:11:57 [foreman-tasks/dynflow] [W] Error on on_execution_plan_save event
 | NoMethodError: undefined method `update_from_dynflow' for nil:NilClass
 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.7.14.4/lib/foreman_tasks/dynflow/persistence.rb:41:in `on_execution_plan_save'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.7.14.4/lib/foreman_tasks/dynflow/persistence.rb:14:in `block in save_execution_plan'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.7.14.4/lib/foreman_tasks/dynflow/persistence.rb:12:in `tap'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.7.14.4/lib/foreman_tasks/dynflow/persistence.rb:12:in `save_execution_plan'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.11/lib/dynflow/persistence.rb:49:in `save_execution_plan'

Comment 10 Sachin Ghai 2016-05-26 07:22:39 UTC

Created attachment 1161766 [details]
complete_exception_snap13.txt

Comment 11 Sachin Ghai 2016-05-26 07:36:30 UTC

Created attachment 1161770 [details]
foreman-debug from recent upgrade with snap13.1

Comment 12 Ohad Levy 2016-05-26 10:56:19 UTC

this looks like the migration did not run, if you execute foreman-rake db:migrate do you get any output?

Comment 13 Brad Buckingham 2016-05-26 21:38:17 UTC

Ivan,  does this one look familiar?  It may be a side affect of other issues, but wanted to make you aware.

Comment 14 Ivan Necas 2016-05-27 08:40:02 UTC

It's as Ohad suggest: it seems migration did not finished but we are already serving requests with the new code. When looking at the logs, the request happened while the installer was in progress but before the installer did the final service restart.

The error from https://bugzilla.redhat.com/show_bug.cgi?id=1337452#c9 seems like a consequence of the previous problem.

The fix should be to refuse any page load when migrations were not finished yet.

Sachin: for future actions, please don't reuse exising bugs unless the error messages are the same as the original description: this complicates the whole process and causes unneeded confusions.

Comment 16 Bryan Kearney 2016-05-31 16:17:37 UTC

Upstream bug assigned to dlobatog

Comment 17 Bryan Kearney 2016-05-31 16:17:41 UTC

Upstream bug assigned to dlobatog

Comment 18 Sachin Ghai 2016-06-02 08:03:57 UTC

Exceptions from comment8 and comment9 are reproducible with snap14 upgrade

Comment 19 Ivan Necas 2016-06-02 12:07:39 UTC

One additional info: the backtraces selves are not fatal and should not affect the rest of the migration process

Comment 21 Sachin Ghai 2016-06-09 08:28:13 UTC

Verified with upgrade from sat6.1.9 -> sat6.2 snap14.1 and 
upgrade from sat6.1.9 -> sat6.2 snap15.0

I'm not able to reproduce the reported issue. looks like it was appearing because of some other issue as stated in comment14. Since i'm not able to reproduce the with latest snap. so closing this now. I'll re-open, if come across again.

Thanks.