Bug #32351: Potential race condition in katello-agent dynflow actions - Katello - Foreman

Actions

Copy link

Bug #32351

closed

Potential race condition in katello-agent dynflow actions

Added by Jonathon Turel over 3 years ago. Updated over 3 years ago.

Status:

Closed

Priority:

Normal

Assignee:

Jonathon Turel

Category:

Client/Agent

Target version:

Katello 4.0.1

Difficulty:

Triaged:

Yes

Bugzilla link:

Pull request:

https://github.com/Katello/katello/pull/9304

Fixed in Releases:

Katello 4.2.0

Found in Releases:

Red Hat JIRA:

Description

Sometimes katello agent actions are resulting in the 'Host did not respond within 20 seconds.' warning. The production.log shows the error below which gives the impression that the transaction in AgentAction#plan was not comitted by the time the DispatchHistory is loaded by the agent event handler.

2021-04-19T17:08:55 [I|app|3d9fe84c] Started PUT "/api/hosts/3/errata/apply" for 192.168.121.68 at 2021-04-19 17:08:55 +0000
2021-04-19T17:08:55 [I|app|3d9fe84c] Processing by Katello::Api::V2::HostErrataController#apply as JSON
2021-04-19T17:08:55 [I|app|3d9fe84c]   Parameters: {"errata_ids"=>["RHEA-2012:0055"], "included"=>{}, "excluded"=>{}, "api_version"=>"v2", "host_id"=>"3", "host_erratum"=>{"errata_ids"=>["RHEA-2012:0055"], "included"=>{}, "excluded"=>{}}}
2021-04-19T17:08:55 [I|app|3d9fe84c] Authorized user admin(Admin User)
2021-04-19T17:08:56 [I|bac|3d9fe84c] Task {label: Actions::Katello::Host::Erratum::Install, id: 0e10aac2-52e6-427e-abae-7bbd30f2b32d, execution_plan_id: 9f83f30d-261a-41b9-a2a8-7526c9de4008} state changed: planning
2021-04-19T17:08:56 [E|app|bbf4e7b3] Error handling Katello Agent client message
2021-04-19T17:08:56 [E|app|bbf4e7b3] No valid dispatch history in client message
2021-04-19T17:08:56 [E|app|bbf4e7b3] /opt/theforeman/tfm/root/usr/share/gems/gems/katello-4.1.0.pre.master/app/lib/katello/agent/client_message_handler.rb:11:in `initialize'
 bbf4e7b3 | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-4.1.0.pre.master/app/lib/katello/event_daemon/services/agent_event_receiver.rb:17:in `new'
 bbf4e7b3 | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-4.1.0.pre.master/app/lib/katello/event_daemon/services/agent_event_receiver.rb:17:in `block in handle'
 bbf4e7b3 | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-4.1.0.pre.master/app/lib/katello/util/support.rb:76:in `with_db_connection'
 bbf4e7b3 | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-4.1.0.pre.master/app/lib/katello/event_daemon/services/agent_event_receiver.rb:16:in `handle'
 bbf4e7b3 | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-4.1.0.pre.master/app/lib/katello/qpid/connection.rb:70:in `on_message'
 bbf4e7b3 | /opt/theforeman/tfm/root/usr/share/gems/gems/qpid_proton-0.33.0/lib/handler/adapter.rb:74:in `forward'
 bbf4e7b3 | /opt/theforeman/tfm/root/usr/share/gems/gems/qpid_proton-0.33.0/lib/handler/messaging_adapter.rb:27:in `delegate'
 bbf4e7b3 | /opt/theforeman/tfm/root/usr/share/gems/gems/qpid_proton-0.33.0/lib/handler/messaging_adapter.rb:108:in `on_delivery'
 bbf4e7b3 | /opt/theforeman/tfm/root/usr/share/gems/gems/qpid_proton-0.33.0/lib/core/event.rb:94:in `dispatch'
 bbf4e7b3 | /opt/theforeman/tfm/root/usr/share/gems/gems/qpid_proton-0.33.0/lib/core/connection_driver.rb:194:in `block in dispatch'
 bbf4e7b3 | /opt/theforeman/tfm/root/usr/share/gems/gems/qpid_proton-0.33.0/lib/core/connection_driver.rb:78:in `each_event'
 bbf4e7b3 | /opt/theforeman/tfm/root/usr/share/gems/gems/qpid_proton-0.33.0/lib/core/connection_driver.rb:188:in `dispatch'
 bbf4e7b3 | /opt/theforeman/tfm/root/usr/share/gems/gems/qpid_proton-0.33.0/lib/core/container.rb:270:in `dispatch'
 bbf4e7b3 | /opt/theforeman/tfm/root/usr/share/gems/gems/qpid_proton-0.33.0/lib/core/connection_driver.rb:204:in `process'
 bbf4e7b3 | /opt/theforeman/tfm/root/usr/share/gems/gems/qpid_proton-0.33.0/lib/core/container.rb:267:in `process'
 bbf4e7b3 | /opt/theforeman/tfm/root/usr/share/gems/gems/qpid_proton-0.33.0/lib/core/container.rb:419:in `block in run_one'
 bbf4e7b3 | /opt/theforeman/tfm/root/usr/share/gems/gems/qpid_proton-0.33.0/lib/core/container.rb:432:in `maybe_panic'
 bbf4e7b3 | /opt/theforeman/tfm/root/usr/share/gems/gems/qpid_proton-0.33.0/lib/core/container.rb:419:in `run_one'
 bbf4e7b3 | /opt/theforeman/tfm/root/usr/share/gems/gems/qpid_proton-0.33.0/lib/core/container.rb:197:in `run'
 bbf4e7b3 | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-4.1.0.pre.master/app/lib/katello/qpid/connection.rb:141:in `with_connection'
 bbf4e7b3 | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-4.1.0.pre.master/app/lib/katello/qpid/connection.rb:126:in `receive_messages'
 bbf4e7b3 | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-4.1.0.pre.master/app/lib/katello/agent/connection.rb:18:in `fetch_agent_messages'
 bbf4e7b3 | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-4.1.0.pre.master/app/lib/katello/event_daemon/services/agent_event_receiver.rb:38:in `block in run'
 bbf4e7b3 | /opt/theforeman/tfm/root/usr/share/gems/gems/logging-2.3.0/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
2021-04-19T17:08:56 [I|bac|3d9fe84c] Task {label: Actions::Katello::Host::Erratum::Install, id: 0e10aac2-52e6-427e-abae-7bbd30f2b32d, execution_plan_id: 9f83f30d-261a-41b9-a2a8-7526c9de4008} state changed: planned

And 20 seconds later the client times out:

    021-04-19T17:09:16 [E|bac|3d9fe84c] Host did not respond within 20 seconds. The task has been cancelled. Is katello-agent installed and goferd running on the Host? (RuntimeError)
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-4.1.0.pre.master/app/lib/actions/katello/agent_action.rb:78:in `process_timeout'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-4.1.0.pre.master/app/lib/actions/katello/agent_action.rb:57:in `run'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/action.rb:571:in `block (3 levels) in execute_run'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware/stack.rb:27:in `pass'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware.rb:19:in `pass'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-4.1.0/app/lib/actions/middleware/rails_executor_wrap.rb:14:in `block in run'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.5/lib/active_support/execution_wrapper.rb:88:in `wrap'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-4.1.0/app/lib/actions/middleware/rails_executor_wrap.rb:13:in `run'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware/stack.rb:23:in `call'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware/stack.rb:27:in `pass'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware.rb:19:in `pass'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/action/progress.rb:31:in `with_progress_calculation'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/action/progress.rb:17:in `run'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware/stack.rb:23:in `call'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware/stack.rb:27:in `pass'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware.rb:19:in `pass'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-4.1.0/app/lib/actions/middleware/keep_current_request_id.rb:15:in `block in run'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-4.1.0/app/lib/actions/middleware/keep_current_request_id.rb:52:in `restore_current_request_id'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-4.1.0/app/lib/actions/middleware/keep_current_request_id.rb:15:in `run'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware/stack.rb:23:in `call'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware/stack.rb:27:in `pass'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware.rb:19:in `pass'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-4.1.0/app/lib/actions/middleware/keep_current_timezone.rb:15:in `block in run'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-4.1.0/app/lib/actions/middleware/keep_current_timezone.rb:44:in `restore_curent_timezone'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-4.1.0/app/lib/actions/middleware/keep_current_timezone.rb:15:in `run'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware/stack.rb:23:in `call'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware/stack.rb:27:in `pass'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware.rb:19:in `pass'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-4.1.0/app/lib/actions/middleware/keep_current_taxonomies.rb:15:in `block in run'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-4.1.0/app/lib/actions/middleware/keep_current_taxonomies.rb:45:in `restore_current_taxonomies'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-4.1.0/app/lib/actions/middleware/keep_current_taxonomies.rb:15:in `run'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware/stack.rb:23:in `call'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware/stack.rb:27:in `pass'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware.rb:19:in `pass'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware.rb:32:in `run'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware/stack.rb:23:in `call'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware/stack.rb:27:in `pass'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware.rb:19:in `pass'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-4.1.0/app/lib/actions/middleware/keep_current_user.rb:15:in `block in run'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-4.1.0/app/lib/actions/middleware/keep_current_user.rb:54:in `restore_curent_user'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-4.1.0/app/lib/actions/middleware/keep_current_user.rb:15:in `run'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware/stack.rb:23:in `call'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware/world.rb:31:in `execute'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/action.rb:570:in `block (2 levels) in execute_run'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/action.rb:569:in `catch'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/action.rb:569:in `block in execute_run'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/action.rb:472:in `block in with_error_handling'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/action.rb:472:in `catch'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/action.rb:472:in `with_error_handling'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/action.rb:564:in `execute_run'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/action.rb:285:in `execute'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:18:in `block (2 levels) in execute'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/execution_plan/steps/abstract.rb:167:in `with_meta_calculation'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:17:in `block in execute'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:32:in `open_action'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:16:in `execute'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/director.rb:93:in `execute'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/executors/sidekiq/worker_jobs.rb:11:in `block (2 levels) in perform'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/executors.rb:18:in `run_user_code'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/executors/sidekiq/worker_jobs.rb:9:in `block in perform'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/executors/sidekiq/worker_jobs.rb:25:in `with_telemetry'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/executors/sidekiq/worker_jobs.rb:8:in `perform'
     3d9fe84c | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/executors/sidekiq/serialization.rb:27:in `perform'
     3d9fe84c | [ sidekiq ]