Bug #10924
open
Getting "cannot accept execution_plan_id core is terminating" when trying to perform tasks
Description
I started getting these today and I have no idea how to resolve them. I've tried cleaning up some failed tasks (duplicate key issues that resolve themselves if I tell the task to resume) and I've tried to clean up the dependent tasks as indicated in the logs. After a few cleanups, with no additional errors, I started getting this for all tasks I've tried to start :
cannot accept execution_plan_id:1da9f49c-0d88-491e-a653-fdf7c047efe0 core is terminating
Dynflow::Error
cannot accept execution_plan_id:1da9f49c-0d88-491e-a653-fdf7c047efe0 core is terminating
app/controllers/concerns/application_shared.rb:13:in `set_timezone'
app/models/concerns/foreman/thread_session.rb:32:in `clear_thread'
lib/middleware/catch_json_parse_errors.rb:9:in `call'
foreman/production.log :
2015-06-24 17:12:00 [I] Processing by Api::V2::ReportsController#create as JSON
2015-06-24 17:12:00 [I] Parameters: {"report"=>"[FILTERED]", "apiv"=>"v2"}
2015-06-24 17:12:00 [I] processing report for test.example.com
2015-06-24 17:12:01 [I] Imported report for test.example.com in 0.16 seconds
2015-06-24 17:12:01 [I] Completed 201 Created in 173ms (Views: 1.4ms | ActiveRecord: 0.0ms)
2015-06-24 17:12:24 [I] Processing by DashboardController#index as HTML
2015-06-24 17:12:24 [I] Redirected to https://katello.example.com/
2015-06-24 17:12:24 [I] Filter chain halted as :require_ssl rendered or redirected
2015-06-24 17:12:24 [I] Completed 302 Found in 1ms (ActiveRecord: 0.0ms)
2015-06-24 17:12:38 [I] Processing by ForemanTasks::Api::TasksController#bulk_search as JSON
2015-06-24 17:12:38 [I] Parameters: {"searches"=>[{"type"=>"resource", "resource_type"=>"Katello::Product", "resource_id"=>"4", "search_id"=>"1"}], "task"=>{}}
2015-06-24 17:12:40 [I] Completed 200 OK in 1686ms (Views: 276.9ms | ActiveRecord: 11.3ms)
2015-06-24 17:12:42 [I] Processing by ForemanTasks::Api::TasksController#bulk_search as JSON
2015-06-24 17:12:42 [I] Parameters: {"searches"=>[{"type"=>"resource", "resource_type"=>"Katello::Product", "resource_id"=>"4", "search_id"=>"1"}], "task"=>{}}
2015-06-24 17:12:44 [I] Completed 200 OK in 1806ms (Views: 270.7ms | ActiveRecord: 11.0ms)
2015-06-24 17:12:45 [I] Processing by ForemanTasks::Api::TasksController#bulk_search as JSON
2015-06-24 17:12:45 [I] Parameters: {"searches"=>[{"type"=>"task", "task_id"=>"89874fe4-6031-4493-854c-a3f1f119e258", "search_id"=>"2"}], "task"=>{}}
2015-06-24 17:12:45 [I] Completed 200 OK in 99ms (Views: 15.3ms | ActiveRecord: 1.6ms)
2015-06-24 17:12:51 [I] Processing by ForemanTasks::TasksController#show as HTML
2015-06-24 17:12:51 [I] Parameters: {"id"=>"89874fe4-6031-4493-854c-a3f1f119e258"}
2015-06-24 17:12:51 [I] Rendered /opt/rh/ruby193/root/usr/share/gems/gems/foreman-tasks-0.6.13/app/views/foreman_tasks/tasks/_details.html.erb (582.4ms)
2015-06-24 17:12:51 [I] Rendered /opt/rh/ruby193/root/usr/share/gems/gems/foreman-tasks-0.6.13/app/views/foreman_tasks/tasks/_running_steps.html.erb (0.1ms)
2015-06-24 17:12:51 [I] Rendered /opt/rh/ruby193/root/usr/share/gems/gems/foreman-tasks-0.6.13/app/views/foreman_tasks/tasks/_errors.html.erb (28.3ms)
2015-06-24 17:12:51 [I] Rendered /opt/rh/ruby193/root/usr/share/gems/gems/foreman-tasks-0.6.13/app/views/foreman_tasks/tasks/_raw.html.erb (39.0ms)
2015-06-24 17:12:51 [I] Rendered /opt/rh/ruby193/root/usr/share/gems/gems/foreman-tasks-0.6.13/app/views/foreman_tasks/tasks/_locks.html.erb (8.7ms)
2015-06-24 17:12:51 [I] Rendered /opt/rh/ruby193/root/usr/share/gems/gems/foreman-tasks-0.6.13/app/views/foreman_tasks/tasks/show.html.erb within layouts/application (810.7ms)
2015-06-24 17:12:51 [I] Rendered home/_user_dropdown.html.erb (1.0ms)
2015-06-24 17:12:51 [I] Read fragment views/tabs_and_title_records-4 (0.1ms)
2015-06-24 17:12:51 [I] Rendered home/_topbar.html.erb (1.7ms)
2015-06-24 17:12:51 [I] Rendered layouts/base.html.erb (2.8ms)
2015-06-24 17:12:51 [I] Completed 200 OK in 825ms (Views: 805.2ms | ActiveRecord: 10.9ms)
2015-06-24 17:13:00 [I] Processing by ForemanTasks::TasksController#resume as HTML
2015-06-24 17:13:00 [I] Parameters: {"authenticity_token"=>"x3Mu1BG+rja+sxAI+stj/40vKkTIgEYkz7IxUFZGLDA=", "id"=>"89874fe4-6031-4493-854c-a3f1f119e258"}
2015-06-24 17:13:00 [E] cannot accept execution_plan_id:1da9f49c-0d88-491e-a653-fdf7c047efe0 core is terminating (Dynflow::Error)
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.8/lib/dynflow/executors/parallel/core.rb:54:in `track_execution_plan'
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.8/lib/dynflow/executors/parallel/core.rb:23:in `block in on_message'
/opt/rh/ruby193/root/usr/share/gems/gems/algebrick-0.4.0/lib/algebrick.rb:859:in `block in assigns'
/opt/rh/ruby193/root/usr/share/gems/gems/algebrick-0.4.0/lib/algebrick.rb:858:in `tap'
/opt/rh/ruby193/root/usr/share/gems/gems/algebrick-0.4.0/lib/algebrick.rb:858:in `assigns'
/opt/rh/ruby193/root/usr/share/gems/gems/algebrick-0.4.0/lib/algebrick.rb:138:in `match_value'
/opt/rh/ruby193/root/usr/share/gems/gems/algebrick-0.4.0/lib/algebrick.rb:116:in `block in match'
/opt/rh/ruby193/root/usr/share/gems/gems/algebrick-0.4.0/lib/algebrick.rb:115:in `each'
/opt/rh/ruby193/root/usr/share/gems/gems/algebrick-0.4.0/lib/algebrick.rb:115:in `match'
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.8/lib/dynflow/executors/parallel/core.rb:21:in `on_message'
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.8/lib/dynflow/micro_actor.rb:80:in `block in on_envelope'
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.8/lib/dynflow/future.rb:75:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.8/lib/dynflow/future.rb:75:in `evaluate_to'
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.8/lib/dynflow/micro_actor.rb:80:in `on_envelope'
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.8/lib/dynflow/micro_actor.rb:72:in `receive'
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.8/lib/dynflow/micro_actor.rb:99:in `block (2 levels) in run'
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.8/lib/dynflow/micro_actor.rb:99:in `loop'
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.8/lib/dynflow/micro_actor.rb:99:in `block in run'
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.8/lib/dynflow/micro_actor.rb:99:in `catch'
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.8/lib/dynflow/micro_actor.rb:99:in `run'
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.8/lib/dynflow/micro_actor.rb:13:in `block in initialize'
/opt/rh/ruby193/root/usr/share/gems/gems/logging-1.8.1/lib/logging/diagnostic_context.rb:323:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/logging-1.8.1/lib/logging/diagnostic_context.rb:323:in `block in create_with_logging_context'
2015-06-24 17:13:00 [E] cannot accept execution_plan_id:1da9f49c-0d88-491e-a653-fdf7c047efe0 core is terminating (Dynflow::Error)
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.8/lib/dynflow/executors/parallel/core.rb:54:in `track_execution_plan'
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.8/lib/dynflow/executors/parallel/core.rb:23:in `block in on_message'
/opt/rh/ruby193/root/usr/share/gems/gems/algebrick-0.4.0/lib/algebrick.rb:859:in `block in assigns'
/opt/rh/ruby193/root/usr/share/gems/gems/algebrick-0.4.0/lib/algebrick.rb:858:in `tap'
/opt/rh/ruby193/root/usr/share/gems/gems/algebrick-0.4.0/lib/algebrick.rb:858:in `assigns'
/opt/rh/ruby193/root/usr/share/gems/gems/algebrick-0.4.0/lib/algebrick.rb:138:in `match_value'
/opt/rh/ruby193/root/usr/share/gems/gems/algebrick-0.4.0/lib/algebrick.rb:116:in `block in match'
/opt/rh/ruby193/root/usr/share/gems/gems/algebrick-0.4.0/lib/algebrick.rb:115:in `each'
/opt/rh/ruby193/root/usr/share/gems/gems/algebrick-0.4.0/lib/algebrick.rb:115:in `match'
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.8/lib/dynflow/executors/parallel/core.rb:21:in `on_message'
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.8/lib/dynflow/micro_actor.rb:80:in `block in on_envelope'
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.8/lib/dynflow/future.rb:75:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.8/lib/dynflow/future.rb:75:in `evaluate_to'
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.8/lib/dynflow/micro_actor.rb:80:in `on_envelope'
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.8/lib/dynflow/micro_actor.rb:72:in `receive'
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.8/lib/dynflow/micro_actor.rb:99:in `block (2 levels) in run'
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.8/lib/dynflow/micro_actor.rb:99:in `loop'
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.8/lib/dynflow/micro_actor.rb:99:in `block in run'
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.8/lib/dynflow/micro_actor.rb:99:in `catch'
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.8/lib/dynflow/micro_actor.rb:99:in `run'
/opt/rh/ruby193/root/usr/share/gems/gems/dynflow-0.7.8/lib/dynflow/micro_actor.rb:13:in `block in initialize'
/opt/rh/ruby193/root/usr/share/gems/gems/logging-1.8.1/lib/logging/diagnostic_context.rb:323:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/logging-1.8.1/lib/logging/diagnostic_context.rb:323:in `block in create_with_logging_context'
2015-06-24 17:13:00 [W] Operation FAILED: cannot accept execution_plan_id:1da9f49c-0d88-491e-a653-fdf7c047efe0 core is terminating
2015-06-24 17:13:00 [I] Rendered common/500.html.erb within layouts/application (2.8ms)
2015-06-24 17:13:00 [I] Rendered layouts/base.html.erb (0.9ms)
2015-06-24 17:13:00 [I] Completed 500 Internal Server Error in 631ms (Views: 5.0ms | ActiveRecord: 1.6ms)
2015-06-24 17:13:24 [I] Processing by DashboardController#index as HTML
2015-06-24 17:13:24 [I] Redirected to https://katello.example.com/
2015-06-24 17:13:24 [I] Filter chain halted as :require_ssl rendered or redirected
2015-06-24 17:13:24 [I] Completed 302 Found in 1ms (ActiveRecord: 0.0ms)
2015-06-24 17:14:24 [I] Processing by DashboardController#index as HTML
2015-06-24 17:14:24 [I] Redirected to https://katello.example.com/
2015-06-24 17:14:24 [I] Filter chain halted as :require_ssl rendered or redirected
2015-06-24 17:14:24 [I] Completed 302 Found in 1ms (ActiveRecord: 0.0ms)
Updated by Dominic Cleal about 9 years ago
- Project changed from Foreman to foreman-tasks
Updated by Ivan Necas almost 9 years ago
Could you check `/var/run/foreman/pids/dynflow_executor.output` for some hints why is this happening?
Updated by Ivan Necas almost 9 years ago
Also, watching the output file, as well as the /var/log/foreman/production.log, while restarting the foreman-tasks service might be useful.
Updated by John Beranek almost 9 years ago
Also getting stuck "Synchronize repository" tasks in my Katello 2.1 installation. Had the error in this ticket's title for some tasks, and others that give out the following error:
Warning!
387: unexpected token at '{"_href":"/pulp/api/v2/tasks/6b0062b8-25b6-4a56-8cb6-a14dc993f9cb/","task_id":"6b0062b8-25b6-4a56-8cb6-a14dc993f9cb","finish_time":"2015-08-08T00:01:13Z","_ns":"task_status","start_time":"2015-08-08T00:01:12Z","traceback":"Traceback (most recent call last):\\n File \\"/usr/lib/python2.6/site-packages/celery/app/trace.py\\", line 240, in trace_task\\n R = retval = fun(*args, **kwargs)\\n File \\"/usr/lib/python2.6/site-packages/pulp/server/async/tasks.py\\", line 315, in __call__\\n return super(Task, self).__call__(*args, **kwargs)\\n File \\"/usr/lib/python2.6/site-packages/celery/app/trace.py\\", line 437, in __protected_call__\\n return self.run(*args, **kwargs)\\n File \\"/usr/lib/python2.6/site-packages/pulp/server/tasks/repository.py\\", line 210, in sync_with_auto_publish\\n sync_result = managers.repo_sync_manager().sync(repo_id, sync_config_override=overrides)\\n File \\"/usr/lib/python2.6/site-packages/pulp/server/managers/repo/sync.py\\", line 113, in sync\\n raise PulpExecutionException(_('Importer indicated a failed response'))\\nPulpExecutionException: Importer indicated a failed response\\n","spawned_tasks":[],"progress_report":{"yum_importer":{"content":{"size_total":0,"items_left":0,"items_total":0,"state":"NOT_STARTED","size_left":0,"details":{"rpm_total":0,"rpm_done":0,"drpm_total":0,"drpm_done":0},"error_details":[]},"comps":{"state":"NOT_STARTED"},"distribution":{"items_total":0,"state":"NOT_STARTED","error_details":[],"items_left":0},"errata":{"state":"NOT_STARTED"},"metadata":{"state":"FAILED","error":"[Errno 185090050] _ssl.c:330: error:0B084002:x509 certificate routines:X509_load_cert_crl_file:system lib"}}},"state":"error","error":{"code":"PLP0000","data":{},"description":"Importer indicated a failed response","sub_errors":[]},"_id":{"$oid":"55c546c81f54e46f3c5a5e15"}}]}}'
Looking my production.log I also see sections like the following:
ActionController::RoutingError (No route matches [GET] "/pulp/repos/My_Organisation/Library/CentOS-6/custom/CentOS/CentOS-6_6-x86_64-updates/repodata/repomd.xml"): /usr/lib/ruby/gems/1.8/gems/passenger-4.0.18/lib/phusion_passenger/rack/thread_handler_extension.rb:77:in `process_request' /usr/lib/ruby/gems/1.8/gems/passenger-4.0.18/lib/phusion_passenger/request_handler/thread_handler.rb:140:in `accept_and_process_next_request' /usr/lib/ruby/gems/1.8/gems/passenger-4.0.18/lib/phusion_passenger/request_handler/thread_handler.rb:108:in `main_loop' /usr/lib/ruby/gems/1.8/gems/passenger-4.0.18/lib/phusion_passenger/request_handler.rb:441:in `block (3 levels) in start_threads'
Updated by Ivan Necas almost 9 years ago
Thanks for reporting.
The routing error seems unrelated, for the parsing issue, I've filed separate bug (with a workaround http://projects.theforeman.org/issues/11580), for the current issuse described here, I'm still looking for more details (reproducer or data I asked previosly http://projects.theforeman.org/projects/foreman-tasks/activity?from=2015-06-30)