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:
Created attachment 1159324 [details] complete exception
Created attachment 1159330 [details] foreman-debug logs
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
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'
Please note that this exception is being raised a bunch of times while running "yum update -y"
Steps taken to reproduce: 1. Set sat6.2 repo on existing sat6.1 setup 2. yum update -y
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'
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'
Created attachment 1161766 [details] complete_exception_snap13.txt
Created attachment 1161770 [details] foreman-debug from recent upgrade with snap13.1
this looks like the migration did not run, if you execute foreman-rake db:migrate do you get any output?
Ivan, does this one look familiar? It may be a side affect of other issues, but wanted to make you aware.
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.
Upstream bug assigned to dlobatog
Exceptions from comment8 and comment9 are reproducible with snap14 upgrade
One additional info: the backtraces selves are not fatal and should not affect the rest of the migration process
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.