Foreman 3.11.1 remoteexecution RuntimeError

Support
1

Problem:
In some cases when running a Job with the “Run Command - Script Default” Template, some Hosts return the expected output and keep running for around 10 minutes until an error messsage “RuntimeError: Unexpected event #<Actions::ProxyAction::ProxyActionStopped: Actions::ProxyAction::ProxyActionStopped>” appears and the job enters failed state.

Expected outcome:
Jobs should get “success” Status after completion

Foreman and Proxy versions:
Foreman + Proxys = 3.11.1

Foreman and Proxy plugin versions:
foreman-tasks 9.1.1
foreman_puppet 6.3.0
foreman_remote_execution 13.1.0
foreman_templates 9.4.0

Distribution and version:
RHEL 8.10

Other relevant data:

Task → Errors:

Output:

{}

Exception:

RuntimeError: Unexpected event #<Actions::ProxyAction::ProxyActionStopped: Actions::ProxyAction::ProxyActionStopped>

Backtrace:

/usr/share/gems/gems/foreman-tasks-9.1.1/app/lib/actions/proxy_action.rb:66:in `block in run'
/usr/share/gems/gems/foreman-tasks-9.1.1/app/lib/actions/proxy_action.rb:239:in `with_connection_error_handling'
/usr/share/gems/gems/foreman-tasks-9.1.1/app/lib/actions/proxy_action.rb:49:in `run'
/usr/share/gems/gems/foreman_remote_execution-13.1.0/app/lib/actions/remote_execution/proxy_action.rb:12:in `block in run'
/usr/share/gems/gems/foreman_remote_execution-13.1.0/app/lib/actions/remote_execution/template_invocation_progress_logging.rb:20:in `block in with_template_invocation_error_logging'
/usr/share/gems/gems/foreman_remote_execution-13.1.0/app/lib/actions/remote_execution/template_invocation_progress_logging.rb:20:in `catch'
/usr/share/gems/gems/foreman_remote_execution-13.1.0/app/lib/actions/remote_execution/template_invocation_progress_logging.rb:20:in `with_template_invocation_error_logging'
/usr/share/gems/gems/foreman_remote_execution-13.1.0/app/lib/actions/remote_execution/proxy_action.rb:12:in `run'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/action.rb:590:in `block (3 levels) in execute_run'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/middleware/stack.rb:28:in `pass'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/middleware.rb:20:in `pass'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/middleware.rb:33:in `run'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/middleware/stack.rb:24:in `call'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/middleware/stack.rb:28:in `pass'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/middleware.rb:20:in `pass'
/usr/share/gems/gems/foreman-tasks-9.1.1/app/lib/actions/middleware/rails_executor_wrap.rb:14:in `block in run'
/usr/share/gems/gems/activesupport-6.1.7.8/lib/active_support/execution_wrapper.rb:91:in `wrap'
/usr/share/gems/gems/foreman-tasks-9.1.1/app/lib/actions/middleware/rails_executor_wrap.rb:13:in `run'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/middleware/stack.rb:24:in `call'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/middleware/stack.rb:28:in `pass'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/middleware.rb:20:in `pass'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/action/progress.rb:29:in `with_progress_calculation'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/action/progress.rb:15:in `run'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/middleware/stack.rb:24:in `call'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/middleware/stack.rb:28:in `pass'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/middleware.rb:20:in `pass'
/usr/share/gems/gems/foreman-tasks-9.1.1/app/lib/actions/middleware/load_setting_values.rb:20:in `run'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/middleware/stack.rb:24:in `call'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/middleware/stack.rb:28:in `pass'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/middleware.rb:20:in `pass'
/usr/share/gems/gems/foreman-tasks-9.1.1/app/lib/actions/middleware/keep_current_request_id.rb:15:in `block in run'
/usr/share/gems/gems/foreman-tasks-9.1.1/app/lib/actions/middleware/keep_current_request_id.rb:52:in `restore_current_request_id'
/usr/share/gems/gems/foreman-tasks-9.1.1/app/lib/actions/middleware/keep_current_request_id.rb:15:in `run'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/middleware/stack.rb:24:in `call'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/middleware/stack.rb:28:in `pass'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/middleware.rb:20:in `pass'
/usr/share/gems/gems/foreman-tasks-9.1.1/app/lib/actions/middleware/keep_current_timezone.rb:15:in `block in run'
/usr/share/gems/gems/foreman-tasks-9.1.1/app/lib/actions/middleware/keep_current_timezone.rb:44:in `restore_curent_timezone'
/usr/share/gems/gems/foreman-tasks-9.1.1/app/lib/actions/middleware/keep_current_timezone.rb:15:in `run'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/middleware/stack.rb:24:in `call'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/middleware/stack.rb:28:in `pass'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/middleware.rb:20:in `pass'
/usr/share/gems/gems/foreman-tasks-9.1.1/app/lib/actions/middleware/keep_current_taxonomies.rb:15:in `block in run'
/usr/share/gems/gems/foreman-tasks-9.1.1/app/lib/actions/middleware/keep_current_taxonomies.rb:45:in `restore_current_taxonomies'
/usr/share/gems/gems/foreman-tasks-9.1.1/app/lib/actions/middleware/keep_current_taxonomies.rb:15:in `run'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/middleware/stack.rb:24:in `call'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/middleware/stack.rb:28:in `pass'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/middleware.rb:20:in `pass'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/middleware.rb:33:in `run'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/middleware/stack.rb:24:in `call'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/middleware/stack.rb:28:in `pass'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/middleware.rb:20:in `pass'
/usr/share/gems/gems/foreman-tasks-9.1.1/app/lib/actions/middleware/keep_current_user.rb:15:in `block in run'
/usr/share/gems/gems/foreman-tasks-9.1.1/app/lib/actions/middleware/keep_current_user.rb:54:in `restore_curent_user'
/usr/share/gems/gems/foreman-tasks-9.1.1/app/lib/actions/middleware/keep_current_user.rb:15:in `run'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/middleware/stack.rb:24:in `call'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/middleware/world.rb:31:in `execute'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/action.rb:589:in `block (2 levels) in execute_run'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/action.rb:588:in `catch'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/action.rb:588:in `block in execute_run'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/action.rb:491:in `block in with_error_handling'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/action.rb:491:in `catch'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/action.rb:491:in `with_error_handling'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/action.rb:583:in `execute_run'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/action.rb:304:in `execute'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:18:in `block (2 levels) in execute'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/execution_plan/steps/abstract.rb:168:in `with_meta_calculation'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:17:in `block in execute'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:32:in `open_action'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:16:in `execute'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/director.rb:95:in `execute'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/executors/sidekiq/worker_jobs.rb:12:in `block (2 levels) in perform'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/executors.rb:18:in `run_user_code'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/executors/sidekiq/worker_jobs.rb:10:in `block in perform'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/executors/sidekiq/worker_jobs.rb:26:in `with_telemetry'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/executors/sidekiq/worker_jobs.rb:9:in `perform'
/usr/share/gems/gems/dynflow-1.8.4/lib/dynflow/executors/sidekiq/serialization.rb:28:in `perform'
/usr/share/gems/gems/sidekiq-6.5.12/lib/sidekiq/processor.rb:202:in `execute_job'
/usr/share/gems/gems/sidekiq-6.5.12/lib/sidekiq/processor.rb:170:in `block (2 levels) in process'
/usr/share/gems/gems/sidekiq-6.5.12/lib/sidekiq/middleware/chain.rb:172:in `invoke'
/usr/share/gems/gems/sidekiq-6.5.12/lib/sidekiq/processor.rb:169:in `block in process'
/usr/share/gems/gems/sidekiq-6.5.12/lib/sidekiq/processor.rb:136:in `block (6 levels) in dispatch'
/usr/share/gems/gems/sidekiq-6.5.12/lib/sidekiq/job_retry.rb:113:in `local'
/usr/share/gems/gems/sidekiq-6.5.12/lib/sidekiq/processor.rb:135:in `block (5 levels) in dispatch'
/usr/share/gems/gems/sidekiq-6.5.12/lib/sidekiq.rb:44:in `block in <module:Sidekiq>'
/usr/share/gems/gems/sidekiq-6.5.12/lib/sidekiq/processor.rb:131:in `block (4 levels) in dispatch'
/usr/share/gems/gems/sidekiq-6.5.12/lib/sidekiq/processor.rb:263:in `stats'
/usr/share/gems/gems/sidekiq-6.5.12/lib/sidekiq/processor.rb:126:in `block (3 levels) in dispatch'
/usr/share/gems/gems/sidekiq-6.5.12/lib/sidekiq/job_logger.rb:13:in `call'
/usr/share/gems/gems/sidekiq-6.5.12/lib/sidekiq/processor.rb:125:in `block (2 levels) in dispatch'
/usr/share/gems/gems/sidekiq-6.5.12/lib/sidekiq/job_retry.rb:80:in `global'
/usr/share/gems/gems/sidekiq-6.5.12/lib/sidekiq/processor.rb:124:in `block in dispatch'
/usr/share/gems/gems/sidekiq-6.5.12/lib/sidekiq/job_logger.rb:39:in `prepare'
/usr/share/gems/gems/sidekiq-6.5.12/lib/sidekiq/processor.rb:123:in `dispatch'
/usr/share/gems/gems/sidekiq-6.5.12/lib/sidekiq/processor.rb:168:in `process'
/usr/share/gems/gems/sidekiq-6.5.12/lib/sidekiq/processor.rb:78:in `process_one'
/usr/share/gems/gems/sidekiq-6.5.12/lib/sidekiq/processor.rb:68:in `run'
/usr/share/gems/gems/sidekiq-6.5.12/lib/sidekiq/component.rb:8:in `watchdog'
/usr/share/gems/gems/sidekiq-6.5.12/lib/sidekiq/component.rb:17:in `block in safe_thread'
/usr/share/gems/gems/logging-2.3.1/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
2

When the job finishes running on the proxy, the proxy calls back to Foreman. Apparently, this callback doesn’t go through. /var/log/foreman-proxy/proxy.log and /var/log/foreman/production.log might have some clues about why it didn’t go through.

Every 10 minutes while the job is running, Foreman checks on the proxy to see if the job is still running there. The case where the job on the proxy already finished wasn’t handled correctly and that leads to the error you see. It should be already fixed in nightlies. However, this is just a symptom and resolving the issue described in the first paragraph should make you not run to this secondary problem at all.

3

Thanks! I’ll have a look into our setup. Is the callback a separte connection opened by the smart-proxy to Foreman? I cant find anything besides this. Foreman :: Plugin Manuals

4

Additionally there is this: Installing Foreman Server nightly on Enterprise Linux
which states I need port 443/tcp from proxy to Foreman for uploading remote execution results. This connection is allowed in my environment and shouldn’t be the problem. I cant find anything related in the logs.

5

Yes

There is more at play than just port being open or not, this kind of issue usually boils down to either plain misconfiguration, wrong set of ssl certs being used or name resolution.

In /var/log/foreman-proxy/proxy.log you should see the callback failing, in /var/log/foreman/production.log you should see the request landing, but probably being refused with 403. The first should definitely say something, unless you’re looking at a wrong proxy. If the latter doesn’t say anything, then the callback is not hitting Foreman at all and you need to figure out where it gets lost.

6

I’ll have a look into this, but other (custom) Templates work just fine, which should rule out dns or cert issues.

Yes, after setting logging from info to debug I see all i need.

7

we finally had time to debug this issue. We tracked all connections foreman → proxy → Host and backwards. we’ve seen all calls working properly and the results were in the db at the end but the task was still running until the error message appears after 10 minutes. Since we had nothing else to debug, we tried to fix it in a desperate attempt and restartet the foreman service. Afterwards jobs are working just fine with expected status. This seems to be a temporary solution and we don’t understand the problem so far.