Bug 1796770

Summary:	Attach/Remove subscriptions task failed when a "after_commit" foreman hook is triggered.
Product:	Red Hat Satellite	Reporter:	Hao Chang Yu <hyu>
Component:	Tasks Plugin	Assignee:	Adam Ruzicka <aruzicka>
Status:	CLOSED ERRATA	QA Contact:	Peter Ondrejka <pondrejk>
Severity:	medium	Docs Contact:
Priority:	medium
Version:	6.6.0	CC:	aruzicka, bkearney, ehelms, jesper.schmidt, satellite6-bugs
Target Milestone:	6.10.0	Keywords:	Triaged
Target Release:	Unused
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:	tfm-rubygem-foreman-tasks-4.0.0	Doc Type:	If docs needed, set a value
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2021-11-16 14:08:51 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:

Description Hao Chang Yu 2020-01-31 07:23:46 UTC

Description of problem:
When user has a hook for host that is listening on "after_commit" event (or any DB callback events). The finalize step of the "Attach subscriptions" task is to update the host subscription facet attributes and host status which will triggered the foreman hook above. Before triggering the foreman hook, foreman_hook tried to set the "User.current.login" to an environment variable (FOREMAN_HOOKS_USER) but failed because "User.current" is not set in the executor.

I set the Component of this bug to "Task plugin". If you think this is the bug of the "Hook plugin" then feel free to set it.

Version-Release number of selected component (if applicable):
6.6

How reproducible:
When there is a hook for host that will trigger by database callback.

Steps to Reproduce:
1. Add any hook script in "/usr/share/foreman/config/hooks/host/managed/after_commit"
2. Restart the satellite
3. Go to the web UI -> Content Hosts -> Attach a subscription to any hosts.

Actual results:
All steps in the task have been completed successfully but the task is still in "running" state and the result is "success"

Expected results:
Task should be in the "stopped" state.

Comment 3 Hao Chang Yu 2020-01-31 07:25:57 UTC

Full traceback from "/var/log/foreman/dynflow_executor.output"

E, [2020-01-31T06:58:19.563048 #39601] ERROR -- /parallel-executor-core/pool default/worker-4: undefined method `login' for nil:NilClass (NoMethodError)
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_hooks-0.3.15/lib/foreman_hooks/util.rb:56:in `exec_hook_int'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_hooks-0.3.15/lib/foreman_hooks/util.rb:44:in `block in exec_hook'
/opt/rh/rh-ruby25/root/usr/share/gems/gems/bundler-1.16.1/lib/bundler.rb:297:in `block in with_clean_env'
/opt/rh/rh-ruby25/root/usr/share/gems/gems/bundler-1.16.1/lib/bundler.rb:540:in `with_env'
/opt/rh/rh-ruby25/root/usr/share/gems/gems/bundler-1.16.1/lib/bundler.rb:297:in `with_clean_env'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_hooks-0.3.15/lib/foreman_hooks/util.rb:44:in `exec_hook'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_hooks-0.3.15/lib/foreman_hooks/callback_hooks.rb:23:in `block (4 levels) in <module:CallbackHooks>'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_hooks-0.3.15/lib/foreman_hooks/callback_hooks.rb:23:in `each'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_hooks-0.3.15/lib/foreman_hooks/callback_hooks.rb:23:in `block (3 levels) in <module:CallbackHooks>'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:426:in `block in make_lambda'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:271:in `block in simple'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:517:in `block in invoke_after'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:517:in `each'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:517:in `invoke_after'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:133:in `run_callbacks'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:816:in `_run_commit_callbacks'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/transactions.rb:346:in `committed!'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract/transaction.rb:128:in `commit_records'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract/transaction.rb:223:in `block in commit_transaction'
/opt/rh/rh-ruby25/root/usr/share/ruby/monitor.rb:226:in `mon_synchronize'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract/transaction.rb:213:in `commit_transaction'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract/transaction.rb:252:in `block in within_new_transaction'
/opt/rh/rh-ruby25/root/usr/share/ruby/monitor.rb:226:in `mon_synchronize'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract/transaction.rb:236:in `within_new_transaction'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract/database_statements.rb:254:in `transaction'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/transactions.rb:212:in `transaction'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.2.3/lib/dynflow/transaction_adapters/active_record.rb:5:in `transaction'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.2.3/lib/dynflow/middleware/common/transaction.rb:15:in `rollback_on_error'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.2.3/lib/dynflow/middleware/common/transaction.rb:9:in `finalize_phase'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.2.3/lib/dynflow/middleware/stack.rb:22:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.2.3/lib/dynflow/middleware/world.rb:30:in `execute'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.2.3/lib/dynflow/director/sequential_manager.rb:26:in `finalize'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.2.3/lib/dynflow/director.rb:67:in `execute'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.2.3/lib/dynflow/executors/parallel/worker.rb:14:in `block in on_message'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.2.3/lib/dynflow/executors.rb:12:in `run_user_code'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.2.3/lib/dynflow/executors/parallel/worker.rb:13:in `on_message'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/context.rb:46:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/executes_context.rb:7:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.2.3/lib/dynflow/actor.rb:26:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/awaits.rb:15:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/sets_results.rb:14:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/buffer.rb:38:in `process_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/buffer.rb:31:in `process_envelopes?'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/buffer.rb:20:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/termination.rb:55:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/removes_child.rb:10:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/sets_results.rb:14:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/core.rb:162:in `process_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/core.rb:96:in `block in on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/core.rb:119:in `block (2 levels) in schedule_execution'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/concurrent-ruby-1.1.4/lib/concurrent/synchronization/mutex_lockable_object.rb:41:in `block in synchronize'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/concurrent-ruby-1.1.4/lib/concurrent/synchronization/mutex_lockable_object.rb:41:in `synchronize'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/concurrent-ruby-1.1.4/lib/concurrent/synchronization/mutex_lockable_object.rb:41:in `synchronize'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/core.rb:116:in `block in schedule_execution'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/concurrent-ruby-1.1.4/lib/concurrent/executor/serialized_execution.rb:18:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/concurrent-ruby-1.1.4/lib/concurrent/executor/serialized_execution.rb:96:in `work'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/concurrent-ruby-1.1.4/lib/concurrent/executor/serialized_execution.rb:77:in `block in call_job'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/concurrent-ruby-1.1.4/lib/concurrent/executor/ruby_thread_pool_executor.rb:348:in `run_task'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/concurrent-ruby-1.1.4/lib/concurrent/executor/ruby_thread_pool_executor.rb:337:in `block (3 levels) in create_worker'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/concurrent-ruby-1.1.4/lib/concurrent/executor/ruby_thread_pool_executor.rb:320:in `loop'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/concurrent-ruby-1.1.4/lib/concurrent/executor/ruby_thread_pool_executor.rb:320:in `block (2 levels) in create_worker'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/concurrent-ruby-1.1.4/lib/concurrent/executor/ruby_thread_pool_executor.rb:319:in `catch'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/concurrent-ruby-1.1.4/lib/concurrent/executor/ruby_thread_pool_executor.rb:319:in `block in create_worker'
/opt/theforeman/tfm/root/usr/share/gems/gems/logging-2.2.2/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
E, [2020-01-31T06:58:19.566678 #39601] ERROR -- /parallel-executor-core: No work but not done (RuntimeError)
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.2.3/lib/dynflow/director/execution_plan_manager.rb:86:in `no_work'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.2.3/lib/dynflow/director/execution_plan_manager.rb:105:in `finish'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.2.3/lib/dynflow/director/execution_plan_manager.rb:51:in `what_is_next'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.2.3/lib/dynflow/director.rb:112:in `work_finished'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.2.3/lib/dynflow/executors/parallel/core.rb:49:in `work_finished'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.2.3/lib/dynflow/actor.rb:6:in `on_message'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.2.3/lib/dynflow/executors/parallel/core.rb:109:in `on_message'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/context.rb:46:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/executes_context.rb:7:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.2.3/lib/dynflow/actor.rb:26:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/awaits.rb:15:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/sets_results.rb:14:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/buffer.rb:38:in `process_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/buffer.rb:31:in `process_envelopes?'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/buffer.rb:20:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/termination.rb:55:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/removes_child.rb:10:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/behaviour/sets_results.rb:14:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/core.rb:162:in `process_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/core.rb:96:in `block in on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/core.rb:119:in `block (2 levels) in schedule_execution'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/concurrent-ruby-1.1.4/lib/concurrent/synchronization/mutex_lockable_object.rb:41:in `block in synchronize'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/concurrent-ruby-1.1.4/lib/concurrent/synchronization/mutex_lockable_object.rb:41:in `synchronize'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/concurrent-ruby-1.1.4/lib/concurrent/synchronization/mutex_lockable_object.rb:41:in `synchronize'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.4.1/lib-edge/concurrent/actor/core.rb:116:in `block in schedule_execution'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/concurrent-ruby-1.1.4/lib/concurrent/executor/serialized_execution.rb:18:in `call'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/concurrent-ruby-1.1.4/lib/concurrent/executor/serialized_execution.rb:96:in `work'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/concurrent-ruby-1.1.4/lib/concurrent/executor/serialized_execution.rb:77:in `block in call_job'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/concurrent-ruby-1.1.4/lib/concurrent/executor/ruby_thread_pool_executor.rb:348:in `run_task'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/concurrent-ruby-1.1.4/lib/concurrent/executor/ruby_thread_pool_executor.rb:337:in `block (3 levels) in create_worker'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/concurrent-ruby-1.1.4/lib/concurrent/executor/ruby_thread_pool_executor.rb:320:in `loop'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/concurrent-ruby-1.1.4/lib/concurrent/executor/ruby_thread_pool_executor.rb:320:in `block (2 levels) in create_worker'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/concurrent-ruby-1.1.4/lib/concurrent/executor/ruby_thread_pool_executor.rb:319:in `catch'
/opt/theforeman/tfm-ror52/root/usr/share/gems/gems/concurrent-ruby-1.1.4/lib/concurrent/executor/ruby_thread_pool_executor.rb:319:in `block in create_worker'
/opt/theforeman/tfm/root/usr/share/gems/gems/logging-2.2.2/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'

Comment 7 JazPerSen 2020-06-05 12:42:37 UTC

We may have the same problem.
Any news here?

Comment 14 Hao Chang Yu 2020-11-18 12:29:41 UTC

Found the root cause and link the upstream fix

Comment 15 Adam Ruzicka 2021-01-19 13:32:28 UTC

Fix for this issue was merged in upstream, moving to POST.

Comment 16 Peter Ondrejka 2021-06-11 08:43:11 UTC

Verified on Satellite 6.10 sn 3

Comment 19 errata-xmlrpc 2021-11-16 14:08:51 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 (Moderate: Satellite 6.10 Release), 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/RHSA-2021:4702