1796770 – Attach/Remove subscriptions task failed when a "after_commit" foreman hook is triggered.

Bug 1796770 - Attach/Remove subscriptions task failed when a "after_commit" foreman hook is triggered.

Summary: Attach/Remove subscriptions task failed when a "after_commit" foreman hook is...

Keywords:
Status:	CLOSED ERRATA
Alias:	None
Product:	Red Hat Satellite
Classification:	Red Hat
Component:	Tasks Plugin
Sub Component:
Version:	6.6.0
Hardware:	Unspecified
OS:	Unspecified
Priority:	medium
Severity:	medium
Target Milestone:	6.10.0
Assignee:	Adam Ruzicka
QA Contact:	Peter Ondrejka
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2020-01-31 07:23 UTC by Hao Chang Yu
Modified:	2023-10-06 19:06 UTC (History)
CC List:	5 users (show)
Fixed In Version:	tfm-rubygem-foreman-tasks-4.0.0
Doc Type:	If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:	2021-11-16 14:08:51 UTC
Target Upstream Version:
Embargoed:

Attachments	(Terms of Use)

Links
System	ID	Priority	Status	Summary	Last Updated
Foreman Issue Tracker	30161	Normal	Closed	Attach/Remove subscriptions task failed when a "after_commit" foreman hook is triggered.	2021-02-19 15:57:27 UTC
Github	theforeman foreman-tasks pull 592	None	closed	Fixes #30161 - Make KeepCurrentUser cover entire transaction in finalize	2021-02-19 15:57:27 UTC
Red Hat Product Errata	RHSA-2021:4702	None	None	None	2021-11-16 14:08:59 UTC

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

Note You need to log in before you can comment on or make changes to this bug.