Foreman 2.1 - package install with ansible on our own - remote-execution dynflow-world not initialized

fgoebel · July 16, 2020, 5:44am

Hello dear foreman-community.
My Name is Fabian and I am relatively new to foreman, also I am an Ops-Guy and do not have very much experience with programming, especially not with ruby.

We evaluate Foreman in our department since a few weeks ago, to better understand what is happening and how foreman works we decided to install Foreman from packages with ansible on our own. We have quite good knowledge on ansible but not on puppet yet.
We have come quite far yet, we are able to install foreman, tftp, dhcp-server with smart proxy, control bind from smart proxy, and configure Foreman completly from ansible. We are able to provision Linux and Windows machines on VMware and are quite happy with foreman so far.

The next Important step for us is to get the ansible-plugin running. I have the Ansible-plugin installed in foreman and have a smart-proxy with the proxy-plugins, I am able to import roles.

I can provision ubuntu machines with an ansible user and a SSH-key.

Then i just wanted to get the remote-execution-ssh part going first.
With this i noticed that redis and dynflow-sidekiq was missing, so I installed it, added systemd services for dynflow-sidekiq@worker and @orchestrator and edited the configuration.

When I now schedule a job on a Linunx machine, I get the following error: (stacktrace below)

ops, we're sorry but something went wrong The Dynflow world was not initialized yet. If your plugin uses it, make sure to call Rails.application.dynflow.require! in some initializer

I have just no more idea were to look after…

So I am aware that installing Foreman this way is very hard, but i learned alot the last weeks about foreman so yeah… I am just hoping someone can point me in the right direction to get this working.
I am sure I am just missing one small step…

I will try to be in irc, but i have no bouncer yet…

Foreman and Proxy versions:
2.1 installed from packages with ansible on our own…
Foreman and Proxy plugin versions:

Distribution and version:
Ubuntu 18.04
Other relevant data:

Stacktrace from above error:

*RuntimeError*
**The Dynflow world was not initialized yet. If your plugin uses it, make sure to call Rails.application.dynflow.require! in some initializer**
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/rails.rb:75:in `world'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/lib/foreman_tasks.rb:23:in `trigger'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/lib/foreman_tasks.rb:29:in `block in trigger_task'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/lib/foreman_tasks.rb:49:in `block in rails_safe_trigger_task'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.2/lib/active_support/dependencies/interlock.rb:48:in `block in permit_concurrent_loads'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.2/lib/active_support/concurrency/share_lock.rb:187:in `yield_shares'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.2/lib/active_support/dependencies/interlock.rb:47:in `permit_concurrent_loads'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/lib/foreman_tasks.rb:48:in `rails_safe_trigger_task'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/lib/foreman_tasks.rb:27:in `trigger_task'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/lib/foreman_tasks.rb:54:in `async_task'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/app/models/foreman_tasks/triggering.rb:65:in `trigger'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman_remote_execution-3.3.1/app/models/job_invocation_composer.rb:370:in `trigger'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman_remote_execution-3.3.1/app/controllers/job_invocations_controller.rb:45:in `create'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.2/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.2/lib/abstract_controller/base.rb:195:in `process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.2/lib/action_controller/metal/rendering.rb:30:in `process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.2/lib/abstract_controller/callbacks.rb:42:in `block in process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.2/lib/active_support/callbacks.rb:112:in `block in run_callbacks'
/usr/share/foreman/app/controllers/concerns/foreman/controller/timezone.rb:10:in `set_timezone'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.2/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
/usr/share/foreman/app/models/concerns/foreman/thread_session.rb:32:in `clear_thread'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.2/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
/usr/share/foreman/app/controllers/concerns/foreman/controller/topbar_sweeper.rb:12:in `set_topbar_sweeper_controller'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.2/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/audited-4.9.0/lib/audited/sweeper.rb:14:in `around'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.2/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/audited-4.9.0/lib/audited/sweeper.rb:14:in `around'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.2/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.2/lib/active_support/callbacks.rb:139:in `run_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.2/lib/abstract_controller/callbacks.rb:41:in `process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.2/lib/action_controller/metal/rescue.rb:22:in `process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.2/lib/action_controller/metal/instrumentation.rb:33:in `block in process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.2/lib/active_support/notifications.rb:180:in `block in instrument'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.2/lib/active_support/notifications/instrumenter.rb:24:in `instrument'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.2/lib/active_support/notifications.rb:180:in `instrument'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.2/lib/action_controller/metal/instrumentation.rb:32:in `process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.2/lib/action_controller/metal/params_wrapper.rb:245:in `process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activerecord-6.0.3.2/lib/active_record/railties/controller_runtime.rb:27:in `process_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.2/lib/abstract_controller/base.rb:136:in `process'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionview-6.0.3.2/lib/action_view/rendering.rb:39:in `process'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.2/lib/action_controller/metal.rb:190:in `dispatch'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.2/lib/action_controller/metal.rb:254:in `dispatch'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.2/lib/action_dispatch/routing/route_set.rb:50:in `dispatch'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.2/lib/action_dispatch/routing/route_set.rb:33:in `serve'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.2/lib/action_dispatch/journey/router.rb:49:in `block in serve'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.2/lib/action_dispatch/journey/router.rb:32:in `each'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.2/lib/action_dispatch/journey/router.rb:32:in `serve'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.2/lib/action_dispatch/routing/route_set.rb:834:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/apipie-dsl-2.2.7/lib/apipie_dsl/static_dispatcher.rb:67:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/apipie-rails-0.5.18/lib/apipie/static_dispatcher.rb:66:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/apipie-rails-0.5.18/lib/apipie/extractor/recorder.rb:137:in `call'
/usr/share/foreman/lib/foreman/middleware/telemetry.rb:10:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/apipie-rails-0.5.18/lib/apipie/middleware/checksum_in_headers.rb:27:in `call'
/usr/share/foreman/lib/foreman/middleware/catch_json_parse_errors.rb:9:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.2.3/lib/rack/tempfile_reaper.rb:15:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.2.3/lib/rack/etag.rb:27:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.2.3/lib/rack/conditional_get.rb:40:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.2.3/lib/rack/head.rb:12:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.2/lib/action_dispatch/http/content_security_policy.rb:18:in `call'
/usr/share/foreman/lib/foreman/middleware/logging_context_session.rb:22:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.2.3/lib/rack/session/abstract/id.rb:266:in `context'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.2.3/lib/rack/session/abstract/id.rb:260:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.2/lib/action_dispatch/middleware/cookies.rb:648:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.2/lib/action_dispatch/middleware/callbacks.rb:27:in `block in call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.2/lib/active_support/callbacks.rb:101:in `run_callbacks'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.2/lib/action_dispatch/middleware/callbacks.rb:26:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.2/lib/action_dispatch/middleware/actionable_exceptions.rb:17:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.2/lib/action_dispatch/middleware/debug_exceptions.rb:32:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.2/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/railties-6.0.3.2/lib/rails/rack/logger.rb:37:in `call_app'
/usr/share/foreman/vendor/ruby/2.5.0/gems/railties-6.0.3.2/lib/rails/rack/logger.rb:28:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sprockets-rails-3.2.1/lib/sprockets/rails/quiet_assets.rb:13:in `call'
/usr/share/foreman/lib/foreman/middleware/logging_context_request.rb:11:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.2/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.2/lib/action_dispatch/middleware/request_id.rb:27:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.2.3/lib/rack/method_override.rb:24:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.2.3/lib/rack/runtime.rb:22:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.2/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.2/lib/action_dispatch/middleware/executor.rb:14:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.2/lib/action_dispatch/middleware/static.rb:126:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.2.3/lib/rack/sendfile.rb:110:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/actionpack-6.0.3.2/lib/action_dispatch/middleware/host_authorization.rb:76:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/secure_headers-6.3.1/lib/secure_headers/middleware.rb:11:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/railties-6.0.3.2/lib/rails/engine.rb:527:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/railties-6.0.3.2/lib/rails/railtie.rb:190:in `public_send'
/usr/share/foreman/vendor/ruby/2.5.0/gems/railties-6.0.3.2/lib/rails/railtie.rb:190:in `method_missing'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.2.3/lib/rack/urlmap.rb:74:in `block in call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.2.3/lib/rack/urlmap.rb:58:in `each'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.2.3/lib/rack/urlmap.rb:58:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/rack-2.2.3/lib/rack/handler/webrick.rb:95:in `service'
/usr/lib/ruby/2.5.0/webrick/httpserver.rb:140:in `service'
/usr/lib/ruby/2.5.0/webrick/httpserver.rb:96:in `run'
/usr/lib/ruby/2.5.0/webrick/server.rb:307:in `block in start_thread'
/usr/share/foreman/vendor/ruby/2.5.0/gems/logging-2.2.2/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'

aruzicka · July 16, 2020, 7:06am

Hi,
how are you running foreman, as in the main web process? Using puma or under passenger?

fgoebel · July 16, 2020, 8:26am

Hey aruzicka,
We installed foreman from packages, i think this runs foreman with its own webserver at localhost:3000 behind an nginx reverse proxy on 443. and I hope this answers the question
(Im sorry neither puma or passenger mean anything to me… I really want to put my cards on the table and hope I learn something on the way)

aruzicka · July 16, 2020, 8:35am

Puma is a webserver written in ruby which is the one that is most likely being used in your deployment. Before we go further, could you verify that by running ps -ef | grep puma and seeing if it finds anything?

fgoebel · July 16, 2020, 8:42am

the command ps -ef | grep puma only shows me using grep…

root      6358  6338  0 10:39 pts/1    00:00:00 grep --color=auto puma

but i found: (yes i am aware that it binds on all ips…)

 foreman-ruby bin/rails server -b 0.0.0.0 -p 3000 -e production -d

aruzicka · July 16, 2020, 9:27am

Are you starting it using the systemd service file provided in foreman-service package or are you using something else?

fgoebel · July 16, 2020, 11:50am

Oh wow… seemed like we used the init.d script to start it…

i now have reset the /etc/default/foreman and installed the package foreman-service

and now i can see some more:

root@foreman:~# ps -ef | grep puma
foreman   3428     1  2 13:31 ?        00:00:25 puma 4.3.5 (tcp://0.0.0.0:3000) [foreman]
foreman   3469  3428  0 13:31 ?        00:00:00 puma: cluster worker 0: 3428 [foreman]
foreman   3474  3428  0 13:31 ?        00:00:00 puma: cluster worker 1: 3428 [foreman]
root      4922  4905  0 13:45 pts/0    00:00:00 grep --color=auto puma

Thank you very much so far! i never noticed the foreman-service before, but now its quite obvious…

And the error mentioned above is gone!
I will have to check if I can run jobs through foreman now.

Thank you!

ekohl · July 16, 2020, 12:01pm

I thought that in recent versions we dropped the init script. Can you check which package /etc/init.d/foreman belongs to?

fgoebel · July 16, 2020, 12:20pm

yes, of course:

root@foreman:~# dpkg -S /etc/init.d/foreman
foreman: /etc/init.d/foreman

fgoebel · July 17, 2020, 7:24am

Hello Again,
I can start a ‘scheduled job’ now, but it fails after a while…

The host I want to run the job on has configured a user with the ssh-key provided for the remote-execution plugin
I can log in to the host from the smart-proxy with the ssh key

Maybe someone has an idea what i have forgotten or what i can check!
Thank you in Advance!

proxy.log

2020-07-17T09:07:21  [D] Executor heartbeat
2020-07-17T09:07:36  [D] Executor heartbeat
2020-07-17T09:07:45  [D] accept: <FOREMAN-IP>:58218
2020-07-17T09:07:45  [D] Rack::Handler::WEBrick is invoked.
2020-07-17T09:07:45 22b8bb13 [I] Started GET /dynflow/tasks/count state=running
2020-07-17T09:07:45 22b8bb13 [I] Finished GET /dynflow/tasks/count with 200 (1.01 ms)
2020-07-17T09:07:45  [D] close: <FOREMAN-IP>:58218
2020-07-17T09:07:45  [D] accept: <FOREMAN-IP>:58220
2020-07-17T09:07:45  [D] Rack::Handler::WEBrick is invoked.
2020-07-17T09:07:45 c0d43462 [I] Started GET /version 
2020-07-17T09:07:45 c0d43462 [I] Finished GET /version with 200 (0.39 ms)
2020-07-17T09:07:45  [D] close: <FOREMAN-IP>:58220
2020-07-17T09:07:45  [D] accept: <FOREMAN-IP>:58222
2020-07-17T09:07:45  [D] Rack::Handler::WEBrick is invoked.
2020-07-17T09:07:45 ec7a3b6b [I] Started POST /dynflow/tasks/launch 
2020-07-17T09:07:45 ec7a3b6b [D] ExecutionPlan d6ad72b7-c1d6-45ce-8541-318c63fdafcb      pending >>  planning
2020-07-17T09:07:45 ec7a3b6b [D]          Step d6ad72b7-c1d6-45ce-8541-318c63fdafcb: 1   pending >>   running in phase     Plan ForemanTasksCore::BatchAction
2020-07-17T09:07:45 ec7a3b6b [D] ExecutionPlan bda44229-56db-4e15-bf4e-49769d9bfc00      pending >>  planning
2020-07-17T09:07:45 ec7a3b6b [D]          Step bda44229-56db-4e15-bf4e-49769d9bfc00: 1   pending >>   running in phase     Plan ForemanRemoteExecutionCore::Actions::RunScript
2020-07-17T09:07:45 ec7a3b6b [D]          Step bda44229-56db-4e15-bf4e-49769d9bfc00: 4   pending >>   running in phase     Plan SmartProxyDynflowCore::Callback::Action
2020-07-17T09:07:45 ec7a3b6b [D]          Step bda44229-56db-4e15-bf4e-49769d9bfc00: 4   running >>   success in phase     Plan SmartProxyDynflowCore::Callback::Action
2020-07-17T09:07:45 ec7a3b6b [D]          Step bda44229-56db-4e15-bf4e-49769d9bfc00: 1   running >>   success in phase     Plan ForemanRemoteExecutionCore::Actions::RunScript
2020-07-17T09:07:45 ec7a3b6b [D] ExecutionPlan bda44229-56db-4e15-bf4e-49769d9bfc00     planning >>   planned
2020-07-17T09:07:45 ec7a3b6b [D]          Step d6ad72b7-c1d6-45ce-8541-318c63fdafcb: 1   running >>   success in phase     Plan ForemanTasksCore::BatchAction
2020-07-17T09:07:45 ec7a3b6b [D] ExecutionPlan d6ad72b7-c1d6-45ce-8541-318c63fdafcb     planning >>   planned
2020-07-17T09:07:45  [D] ExecutionPlan bda44229-56db-4e15-bf4e-49769d9bfc00      planned >>   running
2020-07-17T09:07:45 ec7a3b6b [I] Finished POST /dynflow/tasks/launch with 200 (25.85 ms)
2020-07-17T09:07:45  [D]          Step bda44229-56db-4e15-bf4e-49769d9bfc00: 2   pending >>   running in phase      Run ForemanRemoteExecutionCore::Actions::RunScript
2020-07-17T09:07:45  [D]          Step bda44229-56db-4e15-bf4e-49769d9bfc00: 2   running >> suspended in phase      Run ForemanRemoteExecutionCore::Actions::RunScript
2020-07-17T09:07:45  [D] ExecutionPlan d6ad72b7-c1d6-45ce-8541-318c63fdafcb      planned >>   running
2020-07-17T09:07:45  [D] start runner 49d1f002-9f3f-4fe7-b43a-48f90f58a06d
2020-07-17T09:07:45  [D] copying script to /var/tmp/foreman-ssh-cmd-49d1f002-9f3f-4fe7-b43a-48f90f58a06d/script:
  | echo 'Hello World'
2020-07-17T09:07:45  [D] opening session to adu@karin-boothe.REDACTED.example.com
2020-07-17T09:07:45  [D]          Step d6ad72b7-c1d6-45ce-8541-318c63fdafcb: 2   pending >>   running in phase      Run ForemanTasksCore::BatchAction
2020-07-17T09:07:45  [D]          Step d6ad72b7-c1d6-45ce-8541-318c63fdafcb: 2   running >> suspended in phase      Run ForemanTasksCore::BatchAction
2020-07-17T09:07:46  [D] close: <FOREMAN-IP>:58222
2020-07-17T09:07:46  [D] Sending data to /var/tmp/foreman-ssh-cmd-49d1f002-9f3f-4fe7-b43a-48f90f58a06d/script on remote host:
echo 'Hello World'
2020-07-17T09:07:46  [D] executing script:
  | sh <<WRAPPER
  | (sudo -p 'rex login: ' -u root /var/tmp/foreman-ssh-cmd-49d1f002-9f3f-4fe7-b43a-48f90f58a06d/script < /dev/null; echo \$?>/var/tmp/foreman-ssh-cmd-49d1f002-9f3f-4fe7-b43a-48f90f58a06d/exit_code) | /usr/bin/tee /var/tmp/foreman-ssh-cmd-49d1f002-9f3f-4fe7-b43a-48f90f58a06d/output
  | exit \$(cat /var/tmp/foreman-ssh-cmd-49d1f002-9f3f-4fe7-b43a-48f90f58a06d/exit_code)
  | WRAPPER

2020-07-17T09:07:46  [D] refresh runner 49d1f002-9f3f-4fe7-b43a-48f90f58a06d
2020-07-17T09:07:46  [D] refreshing runner
2020-07-17T09:07:46  [D] planning to refresh 49d1f002-9f3f-4fe7-b43a-48f90f58a06d
2020-07-17T09:07:47  [D] Ticker ticking for 1 events
2020-07-17T09:07:47  [D] refresh runner 49d1f002-9f3f-4fe7-b43a-48f90f58a06d
2020-07-17T09:07:47  [D] refreshing runner
2020-07-17T09:07:47  [D] planning to refresh 49d1f002-9f3f-4fe7-b43a-48f90f58a06d
2020-07-17T09:07:48  [D] Ticker ticking for 1 events
2020-07-17T09:07:48  [D] refresh runner 49d1f002-9f3f-4fe7-b43a-48f90f58a06d
2020-07-17T09:07:48  [D] refreshing runner
2020-07-17T09:07:48  [D] finish runner 49d1f002-9f3f-4fe7-b43a-48f90f58a06d
2020-07-17T09:07:48  [D] closing session for command [49d1f002-9f3f-4fe7-b43a-48f90f58a06d],0 actors left 
2020-07-17T09:07:48  [D] terminate 49d1f002-9f3f-4fe7-b43a-48f90f58a06d
2020-07-17T09:07:48  [D]          Step bda44229-56db-4e15-bf4e-49769d9bfc00: 2 got event #<ForemanTasksCore::Runner::Update:0x00005622d70b88f8>
2020-07-17T09:07:48  [D]          Step bda44229-56db-4e15-bf4e-49769d9bfc00: 2 suspended >>   running in phase      Run ForemanRemoteExecutionCore::Actions::RunScript
2020-07-17T09:07:48  [D]          Step bda44229-56db-4e15-bf4e-49769d9bfc00: 2   running >>   success in phase      Run ForemanRemoteExecutionCore::Actions::RunScript
2020-07-17T09:07:48  [D]          Step bda44229-56db-4e15-bf4e-49769d9bfc00: 5   pending >>   running in phase      Run SmartProxyDynflowCore::Callback::Action
2020-07-17T09:07:48  [W] Error details: <NoMethodError>: undefined method `+' for nil:NilClass
/usr/lib/ruby/vendor_ruby/smart_proxy_dynflow_core/callback.rb:61:in `callback_resource'
/usr/lib/ruby/vendor_ruby/smart_proxy_dynflow_core/callback.rb:51:in `callback'
/usr/lib/ruby/vendor_ruby/smart_proxy_dynflow_core/callback.rb:15:in `send_to_foreman_tasks'
/usr/lib/ruby/vendor_ruby/smart_proxy_dynflow_core/callback.rb:72:in `run'
/usr/lib/ruby/vendor_ruby/dynflow/action.rb:563:in `block (3 levels) in execute_run'
/usr/lib/ruby/vendor_ruby/dynflow/middleware/stack.rb:27:in `pass'
/usr/lib/ruby/vendor_ruby/dynflow/middleware.rb:19:in `pass'
/usr/lib/ruby/vendor_ruby/dynflow/action/progress.rb:31:in `with_progress_calculation'
/usr/lib/ruby/vendor_ruby/dynflow/action/progress.rb:17:in `run'
/usr/lib/ruby/vendor_ruby/dynflow/middleware/stack.rb:23:in `call'
/usr/lib/ruby/vendor_ruby/dynflow/middleware/stack.rb:27:in `pass'
/usr/lib/ruby/vendor_ruby/dynflow/middleware.rb:19:in `pass'
/usr/lib/ruby/vendor_ruby/dynflow/middleware.rb:32:in `run'
/usr/lib/ruby/vendor_ruby/dynflow/middleware/stack.rb:23:in `call'
/usr/lib/ruby/vendor_ruby/dynflow/middleware/world.rb:31:in `execute'
/usr/lib/ruby/vendor_ruby/dynflow/action.rb:562:in `block (2 levels) in execute_run'
/usr/lib/ruby/vendor_ruby/dynflow/action.rb:561:in `catch'
/usr/lib/ruby/vendor_ruby/dynflow/action.rb:561:in `block in execute_run'
/usr/lib/ruby/vendor_ruby/dynflow/action.rb:475:in `block in with_error_handling'
/usr/lib/ruby/vendor_ruby/dynflow/action.rb:475:in `catch'
/usr/lib/ruby/vendor_ruby/dynflow/action.rb:475:in `with_error_handling'
/usr/lib/ruby/vendor_ruby/dynflow/action.rb:556:in `execute_run'
/usr/lib/ruby/vendor_ruby/dynflow/action.rb:285:in `execute'
/usr/lib/ruby/vendor_ruby/dynflow/execution_plan/steps/abstract_flow_step.rb:18:in `block (2 levels) in execute'
/usr/lib/ruby/vendor_ruby/dynflow/execution_plan/steps/abstract.rb:167:in `with_meta_calculation'
/usr/lib/ruby/vendor_ruby/dynflow/execution_plan/steps/abstract_flow_step.rb:17:in `block in execute'
/usr/lib/ruby/vendor_ruby/dynflow/execution_plan/steps/abstract_flow_step.rb:32:in `open_action'
/usr/lib/ruby/vendor_ruby/dynflow/execution_plan/steps/abstract_flow_step.rb:16:in `execute'
/usr/lib/ruby/vendor_ruby/dynflow/director.rb:68:in `execute'
/usr/lib/ruby/vendor_ruby/dynflow/executors/parallel/worker.rb:15:in `block in on_message'
/usr/lib/ruby/vendor_ruby/dynflow/executors.rb:18:in `run_user_code'
/usr/lib/ruby/vendor_ruby/dynflow/executors/parallel/worker.rb:14:in `on_message'
/usr/lib/ruby/vendor_ruby/concurrent/actor/context.rb:46:in `on_envelope'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/executes_context.rb:7:in `on_envelope'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/usr/lib/ruby/vendor_ruby/dynflow/actor.rb:106:in `on_envelope'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/awaits.rb:15:in `on_envelope'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/sets_results.rb:14:in `on_envelope'
/usr/lib/ruby/vendor_ruby/dynflow/actor.rb:47:in `block in on_envelope'
/usr/lib/ruby/vendor_ruby/dynflow/actor.rb:59:in `with_backtrace'
/usr/lib/ruby/vendor_ruby/dynflow/actor.rb:47:in `on_envelope'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/buffer.rb:38:in `process_envelope'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/buffer.rb:31:in `process_envelopes?'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/buffer.rb:20:in `on_envelope'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/termination.rb:55:in `on_envelope'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/removes_child.rb:10:in `on_envelope'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/sets_results.rb:14:in `on_envelope'
/usr/lib/ruby/vendor_ruby/concurrent/actor/core.rb:162:in `process_envelope'
/usr/lib/ruby/vendor_ruby/concurrent/actor/core.rb:96:in `block in on_envelope'
/usr/lib/ruby/vendor_ruby/concurrent/actor/core.rb:119:in `block (2 levels) in schedule_execution'
/usr/lib/ruby/vendor_ruby/concurrent/synchronization/mutex_lockable_object.rb:41:in `block in synchronize'
/usr/lib/ruby/vendor_ruby/concurrent/synchronization/mutex_lockable_object.rb:41:in `synchronize'
/usr/lib/ruby/vendor_ruby/concurrent/synchronization/mutex_lockable_object.rb:41:in `synchronize'
/usr/lib/ruby/vendor_ruby/concurrent/actor/core.rb:116:in `block in schedule_execution'
/usr/lib/ruby/vendor_ruby/concurrent/executor/serialized_execution.rb:18:in `call'
/usr/lib/ruby/vendor_ruby/concurrent/executor/serialized_execution.rb:96:in `work'
/usr/lib/ruby/vendor_ruby/concurrent/executor/serialized_execution.rb:77:in `block in call_job'
/usr/lib/ruby/vendor_ruby/concurrent/executor/ruby_thread_pool_executor.rb:353:in `run_task'
/usr/lib/ruby/vendor_ruby/concurrent/executor/ruby_thread_pool_executor.rb:342:in `block (3 levels) in create_worker'
/usr/lib/ruby/vendor_ruby/concurrent/executor/ruby_thread_pool_executor.rb:325:in `loop'
/usr/lib/ruby/vendor_ruby/concurrent/executor/ruby_thread_pool_executor.rb:325:in `block (2 levels) in create_worker'
/usr/lib/ruby/vendor_ruby/concurrent/executor/ruby_thread_pool_executor.rb:324:in `catch'
/usr/lib/ruby/vendor_ruby/concurrent/executor/ruby_thread_pool_executor.rb:324:in `block in create_worker'
/usr/lib/ruby/vendor_ruby/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
2020-07-17T09:07:48  [E] undefined method `+' for nil:NilClass (NoMethodError)
2020-07-17T09:07:48  [D]          Step bda44229-56db-4e15-bf4e-49769d9bfc00: 5   running >>     error in phase      Run SmartProxyDynflowCore::Callback::Action
2020-07-17T09:07:48  [D] ExecutionPlan bda44229-56db-4e15-bf4e-49769d9bfc00      running >>    paused
2020-07-17T09:07:51  [D] Executor heartbeat
2020-07-17T09:07:51  [D] accept: <FOREMAN-IP>:58252
2020-07-17T09:07:51  [D] Rack::Handler::WEBrick is invoked.
2020-07-17T09:07:51 1adca4f1 [I] Started GET /dynflow/tasks/bda44229-56db-4e15-bf4e-49769d9bfc00/status 
2020-07-17T09:07:51 1adca4f1 [I] Finished GET /dynflow/tasks/bda44229-56db-4e15-bf4e-49769d9bfc00/status with 200 (5.27 ms)
2020-07-17T09:07:51  [D] close: <FOREMAN-IP>:58252
2020-07-17T09:07:53  [D] accept: <FOREMAN-IP>:58260
2020-07-17T09:07:53  [D] Rack::Handler::WEBrick is invoked.
2020-07-17T09:07:53 3f42235d [I] Started GET /dynflow/tasks/bda44229-56db-4e15-bf4e-49769d9bfc00/status 
2020-07-17T09:07:53 3f42235d [I] Finished GET /dynflow/tasks/bda44229-56db-4e15-bf4e-49769d9bfc00/status with 200 (3.67 ms)
2020-07-17T09:07:53  [D] close: <FOREMAN-IP>:58260
2020-07-17T09:07:54  [D] accept: <FOREMAN-IP>:58264
2020-07-17T09:07:55  [D] Rack::Handler::WEBrick is invoked.
2020-07-17T09:07:55 2bbb8d2f [I] Started GET /dynflow/tasks/bda44229-56db-4e15-bf4e-49769d9bfc00/status 
2020-07-17T09:07:55 2bbb8d2f [I] Finished GET /dynflow/tasks/bda44229-56db-4e15-bf4e-49769d9bfc00/status with 200 (3.55 ms)
2020-07-17T09:07:55  [D] close: <FOREMAN-IP>:58264
2020-07-17T09:07:55  [D]          Step d6ad72b7-c1d6-45ce-8541-318c63fdafcb: 2 got event Dynflow::Action::WithPollingSubPlans::Poll
2020-07-17T09:07:55  [D]          Step d6ad72b7-c1d6-45ce-8541-318c63fdafcb: 2 suspended >>   running in phase      Run ForemanTasksCore::BatchAction
2020-07-17T09:07:55  [W] Error details: <RuntimeError>: A sub task failed
/usr/lib/ruby/vendor_ruby/dynflow/action/with_sub_plans.rb:231:in `check_for_errors!'
/usr/lib/ruby/vendor_ruby/dynflow/action/with_sub_plans.rb:137:in `try_to_finish'
/usr/lib/ruby/vendor_ruby/dynflow/action/with_polling_sub_plans.rb:19:in `poll'
/usr/lib/ruby/vendor_ruby/dynflow/action/with_polling_sub_plans.rb:11:in `run'
/usr/lib/ruby/vendor_ruby/dynflow/action.rb:563:in `block (3 levels) in execute_run'
/usr/lib/ruby/vendor_ruby/dynflow/middleware/stack.rb:27:in `pass'
/usr/lib/ruby/vendor_ruby/dynflow/middleware.rb:19:in `pass'
/usr/lib/ruby/vendor_ruby/dynflow/action/progress.rb:31:in `with_progress_calculation'
/usr/lib/ruby/vendor_ruby/dynflow/action/progress.rb:17:in `run'
/usr/lib/ruby/vendor_ruby/dynflow/middleware/stack.rb:23:in `call'
/usr/lib/ruby/vendor_ruby/dynflow/middleware/stack.rb:27:in `pass'
/usr/lib/ruby/vendor_ruby/dynflow/middleware.rb:19:in `pass'
/usr/lib/ruby/vendor_ruby/dynflow/middleware.rb:32:in `run'
/usr/lib/ruby/vendor_ruby/dynflow/middleware/stack.rb:23:in `call'
/usr/lib/ruby/vendor_ruby/dynflow/middleware/world.rb:31:in `execute'
/usr/lib/ruby/vendor_ruby/dynflow/action.rb:562:in `block (2 levels) in execute_run'
/usr/lib/ruby/vendor_ruby/dynflow/action.rb:561:in `catch'
/usr/lib/ruby/vendor_ruby/dynflow/action.rb:561:in `block in execute_run'
/usr/lib/ruby/vendor_ruby/dynflow/action.rb:475:in `block in with_error_handling'
/usr/lib/ruby/vendor_ruby/dynflow/action.rb:475:in `catch'
/usr/lib/ruby/vendor_ruby/dynflow/action.rb:475:in `with_error_handling'
/usr/lib/ruby/vendor_ruby/dynflow/action.rb:556:in `execute_run'
/usr/lib/ruby/vendor_ruby/dynflow/action.rb:285:in `execute'
/usr/lib/ruby/vendor_ruby/dynflow/execution_plan/steps/abstract_flow_step.rb:18:in `block (2 levels) in execute'
/usr/lib/ruby/vendor_ruby/dynflow/execution_plan/steps/abstract.rb:167:in `with_meta_calculation'
/usr/lib/ruby/vendor_ruby/dynflow/execution_plan/steps/abstract_flow_step.rb:17:in `block in execute'
/usr/lib/ruby/vendor_ruby/dynflow/execution_plan/steps/abstract_flow_step.rb:32:in `open_action'
/usr/lib/ruby/vendor_ruby/dynflow/execution_plan/steps/abstract_flow_step.rb:16:in `execute'
/usr/lib/ruby/vendor_ruby/dynflow/director.rb:93:in `execute'
/usr/lib/ruby/vendor_ruby/dynflow/executors/parallel/worker.rb:15:in `block in on_message'
/usr/lib/ruby/vendor_ruby/dynflow/executors.rb:18:in `run_user_code'
/usr/lib/ruby/vendor_ruby/dynflow/executors/parallel/worker.rb:14:in `on_message'
/usr/lib/ruby/vendor_ruby/concurrent/actor/context.rb:46:in `on_envelope'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/executes_context.rb:7:in `on_envelope'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/usr/lib/ruby/vendor_ruby/dynflow/actor.rb:106:in `on_envelope'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/awaits.rb:15:in `on_envelope'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/sets_results.rb:14:in `on_envelope'
/usr/lib/ruby/vendor_ruby/dynflow/actor.rb:47:in `block in on_envelope'
/usr/lib/ruby/vendor_ruby/dynflow/actor.rb:59:in `with_backtrace'
/usr/lib/ruby/vendor_ruby/dynflow/actor.rb:47:in `on_envelope'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/buffer.rb:38:in `process_envelope'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/buffer.rb:31:in `process_envelopes?'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/buffer.rb:20:in `on_envelope'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/termination.rb:55:in `on_envelope'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/removes_child.rb:10:in `on_envelope'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/usr/lib/ruby/vendor_ruby/concurrent/actor/behaviour/sets_results.rb:14:in `on_envelope'
/usr/lib/ruby/vendor_ruby/concurrent/actor/core.rb:162:in `process_envelope'
/usr/lib/ruby/vendor_ruby/concurrent/actor/core.rb:96:in `block in on_envelope'
/usr/lib/ruby/vendor_ruby/concurrent/actor/core.rb:119:in `block (2 levels) in schedule_execution'
/usr/lib/ruby/vendor_ruby/concurrent/synchronization/mutex_lockable_object.rb:41:in `block in synchronize'
/usr/lib/ruby/vendor_ruby/concurrent/synchronization/mutex_lockable_object.rb:41:in `synchronize'
/usr/lib/ruby/vendor_ruby/concurrent/synchronization/mutex_lockable_object.rb:41:in `synchronize'
/usr/lib/ruby/vendor_ruby/concurrent/actor/core.rb:116:in `block in schedule_execution'
/usr/lib/ruby/vendor_ruby/concurrent/executor/serialized_execution.rb:18:in `call'
/usr/lib/ruby/vendor_ruby/concurrent/executor/serialized_execution.rb:96:in `work'
/usr/lib/ruby/vendor_ruby/concurrent/executor/serialized_execution.rb:77:in `block in call_job'
/usr/lib/ruby/vendor_ruby/concurrent/executor/ruby_thread_pool_executor.rb:353:in `run_task'
/usr/lib/ruby/vendor_ruby/concurrent/executor/ruby_thread_pool_executor.rb:342:in `block (3 levels) in create_worker'
/usr/lib/ruby/vendor_ruby/concurrent/executor/ruby_thread_pool_executor.rb:325:in `loop'
/usr/lib/ruby/vendor_ruby/concurrent/executor/ruby_thread_pool_executor.rb:325:in `block (2 levels) in create_worker'
/usr/lib/ruby/vendor_ruby/concurrent/executor/ruby_thread_pool_executor.rb:324:in `catch'
/usr/lib/ruby/vendor_ruby/concurrent/executor/ruby_thread_pool_executor.rb:324:in `block in create_worker'
/usr/lib/ruby/vendor_ruby/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
2020-07-17T09:07:55  [E] A sub task failed (RuntimeError)
2020-07-17T09:07:55  [D]          Step d6ad72b7-c1d6-45ce-8541-318c63fdafcb: 2   running >>     error in phase      Run ForemanTasksCore::BatchAction
2020-07-17T09:07:55  [D] ExecutionPlan d6ad72b7-c1d6-45ce-8541-318c63fdafcb      running >>   stopped
2020-07-17T09:07:56  [D] accept: <FOREMAN-IP>:58268
2020-07-17T09:07:56  [D] Rack::Handler::WEBrick is invoked.
2020-07-17T09:07:56 c206689e [I] Started GET /dynflow/tasks/bda44229-56db-4e15-bf4e-49769d9bfc00/status 
2020-07-17T09:07:56 c206689e [I] Finished GET /dynflow/tasks/bda44229-56db-4e15-bf4e-49769d9bfc00/status with 200 (3.53 ms)
2020-07-17T09:07:56  [D] close: <FOREMAN-IP>:58268
2020-07-17T09:07:57  [D] accept: <FOREMAN-IP>:58274
2020-07-17T09:07:57  [D] Rack::Handler::WEBrick is invoked.
2020-07-17T09:07:57 3a7e7378 [I] Started GET /dynflow/tasks/bda44229-56db-4e15-bf4e-49769d9bfc00/status 
2020-07-17T09:07:57 3a7e7378 [I] Finished GET /dynflow/tasks/bda44229-56db-4e15-bf4e-49769d9bfc00/status with 200 (3.58 ms)
2020-07-17T09:07:57  [D] close: <FOREMAN-IP>:58274
2020-07-17T09:07:58  [D] accept: <FOREMAN-IP>:58278
2020-07-17T09:07:58  [D] Rack::Handler::WEBrick is invoked.
2020-07-17T09:07:58 276edd68 [I] Started GET /dynflow/tasks/bda44229-56db-4e15-bf4e-49769d9bfc00/status 
2020-07-17T09:07:58 276edd68 [I] Finished GET /dynflow/tasks/bda44229-56db-4e15-bf4e-49769d9bfc00/status with 200 (3.55 ms)
2020-07-17T09:07:58  [D] close: <FOREMAN-IP>:58278
2020-07-17T09:07:59  [D] accept: <FOREMAN-IP>:58282

Backtrace from job: Remote action: Run echo ‘hello world’ on karin-boothe

/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/app/lib/actions/proxy_action.rb:90:in `check_task_status'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/app/lib/actions/proxy_action.rb:137:in `on_proxy_action_stopped'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/app/lib/actions/proxy_action.rb:56:in `block in run'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/app/lib/actions/proxy_action.rb:237:in `with_connection_error_handling'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/app/lib/actions/proxy_action.rb:41:in `run'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/action.rb:563:in `block (3 levels) in execute_run'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:27:in `pass'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware.rb:19:in `pass'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware.rb:32:in `run'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:23:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:27:in `pass'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware.rb:19:in `pass'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/app/lib/actions/middleware/rails_executor_wrap.rb:14:in `block in run'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.2/lib/active_support/execution_wrapper.rb:88:in `wrap'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/app/lib/actions/middleware/rails_executor_wrap.rb:13:in `run'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:23:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:27:in `pass'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware.rb:19:in `pass'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/action/progress.rb:31:in `with_progress_calculation'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/action/progress.rb:17:in `run'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:23:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:27:in `pass'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware.rb:19:in `pass'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/app/lib/actions/middleware/keep_current_request_id.rb:15:in `block in run'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/app/lib/actions/middleware/keep_current_request_id.rb:49:in `restore_current_request_id'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/app/lib/actions/middleware/keep_current_request_id.rb:15:in `run'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:23:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:27:in `pass'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware.rb:19:in `pass'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/app/lib/actions/middleware/keep_current_timezone.rb:15:in `block in run'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/app/lib/actions/middleware/keep_current_timezone.rb:44:in `restore_curent_timezone'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/app/lib/actions/middleware/keep_current_timezone.rb:15:in `run'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:23:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:27:in `pass'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware.rb:19:in `pass'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/app/lib/actions/middleware/keep_current_user.rb:15:in `block in run'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/app/lib/actions/middleware/keep_current_user.rb:44:in `restore_curent_user'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/app/lib/actions/middleware/keep_current_user.rb:15:in `run'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:23:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:27:in `pass'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware.rb:19:in `pass'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/app/lib/actions/middleware/keep_current_taxonomies.rb:15:in `block in run'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/app/lib/actions/middleware/keep_current_taxonomies.rb:45:in `restore_current_taxonomies'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/app/lib/actions/middleware/keep_current_taxonomies.rb:15:in `run'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:23:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:27:in `pass'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware.rb:19:in `pass'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware.rb:32:in `run'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:23:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware/world.rb:31:in `execute'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/action.rb:562:in `block (2 levels) in execute_run'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/action.rb:561:in `catch'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/action.rb:561:in `block in execute_run'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/action.rb:475:in `block in with_error_handling'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/action.rb:475:in `catch'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/action.rb:475:in `with_error_handling'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/action.rb:556:in `execute_run'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/action.rb:285:in `execute'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:18:in `block (2 levels) in execute'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/execution_plan/steps/abstract.rb:167:in `with_meta_calculation'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:17:in `block in execute'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:32:in `open_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:16:in `execute'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/director.rb:93:in `execute'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/executors/sidekiq/worker_jobs.rb:11:in `block (2 levels) in perform'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/executors.rb:18:in `run_user_code'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/executors/sidekiq/worker_jobs.rb:9:in `block in perform'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/executors/sidekiq/worker_jobs.rb:25:in `with_telemetry'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/executors/sidekiq/worker_jobs.rb:8:in `perform'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/executors/sidekiq/serialization.rb:27:in `perform'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/processor.rb:192:in `execute_job'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/processor.rb:165:in `block (2 levels) in process'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/middleware/chain.rb:128:in `block in invoke'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/middleware/chain.rb:133:in `invoke'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/processor.rb:164:in `block in process'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/processor.rb:137:in `block (6 levels) in dispatch'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/job_retry.rb:109:in `local'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/processor.rb:136:in `block (5 levels) in dispatch'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq.rb:37:in `block in <module:Sidekiq>'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/processor.rb:132:in `block (4 levels) in dispatch'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/processor.rb:250:in `stats'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/processor.rb:127:in `block (3 levels) in dispatch'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/job_logger.rb:8:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/processor.rb:126:in `block (2 levels) in dispatch'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/job_retry.rb:74:in `global'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/processor.rb:125:in `block in dispatch'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/logging.rb:48:in `with_context'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/logging.rb:42:in `with_job_hash_context'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/processor.rb:124:in `dispatch'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/processor.rb:163:in `process'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/processor.rb:83:in `process_one'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/processor.rb:71:in `run'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/util.rb:16:in `watchdog'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/util.rb:25:in `block in safe_thread'
/usr/share/foreman/vendor/ruby/2.5.0/gems/logging-2.2.2/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'

aruzicka · July 17, 2020, 8:00am

You most likely don’t have foreman_url set in foreman proxy settings

ekohl · July 17, 2020, 10:40am

@aruzicka you can enforce this in the plugin. Sadly, the only example that does this is using after_activation which uses the LegacyModuleLoader.

https://github.com/theforeman/smart-proxy/blob/e138e2309d38eabc06b7251f15ad28ad5a264c4f/modules/templates/templates_plugin.rb#L10-L12

If the plugin needs this, I think it would better to fail up front rather than to fail somewhere during execution. If so, we can think of a way to properly support this in the Smart Proxy Plugin API.

fgoebel · July 20, 2020, 7:13am

Hello,
I have just checked this and you were right, foreman_url was not set, I think because “it didnt threw an error if absent”

I can see the output of the command now, but the job keeps in 100% pending and fails after 10 Minutes.

There is only one subtask “Remote action: Run uname -a on van-jiminez.redacted.example.com”, wich fails with the Error below.

Could this be an issue with our SSL-setup?
We use an official wildcard cert for foreman (at nginx) and self-signed certs for the proxies…

Thank you very much!
with kind regards, Fabian

Action:
Actions::ProxyAction
Input:
{"proxy_operation_name"=>"ssh",
 "ssh_user"=>"adu",
 "effective_user"=>"root",
 "effective_user_method"=>"sudo",
 "cleanup_working_dirs"=>true,
 "ssh_port"=>22,
 "hostname"=>"van-jiminez.redacted.example.com",
 "script"=>"uname -a",
 "execution_timeout_interval"=>nil,
 "use_batch_triggering"=>true,
 "use_concurrency_control"=>false,
 "connection_options"=>
  {"retry_interval"=>15, "retry_count"=>4, "proxy_batch_triggering"=>true},
 "proxy_url"=>"https://foreman.redacted.example.com:8443",
 "proxy_action_name"=>"ForemanRemoteExecutionCore::Actions::RunScript",
 "proxy_version"=>{"major"=>2, "minor"=>1, "patch"=>0},
 "current_request_id"=>nil,
 "current_timezone"=>"Europe/Berlin",
 "current_user_id"=>36,
 "current_organization_id"=>nil,
 "current_location_id"=>nil}
Output:
{"proxy_task_id"=>"1eacd2cc-940a-4e12-b255-db3eea54839a"}
Exception:
Foreman::Exception: ERF42-0639 [Foreman::Exception]: The smart proxy task 1eacd2cc-940a-4e12-b255-db3eea54839a failed.
Backtrace:
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/app/lib/actions/proxy_action.rb:90:in `check_task_status'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/app/lib/actions/proxy_action.rb:137:in `on_proxy_action_stopped'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/app/lib/actions/proxy_action.rb:56:in `block in run'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/app/lib/actions/proxy_action.rb:237:in `with_connection_error_handling'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/app/lib/actions/proxy_action.rb:41:in `run'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/action.rb:563:in `block (3 levels) in execute_run'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:27:in `pass'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware.rb:19:in `pass'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware.rb:32:in `run'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:23:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:27:in `pass'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware.rb:19:in `pass'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/app/lib/actions/middleware/rails_executor_wrap.rb:14:in `block in run'
/usr/share/foreman/vendor/ruby/2.5.0/gems/activesupport-6.0.3.2/lib/active_support/execution_wrapper.rb:88:in `wrap'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/app/lib/actions/middleware/rails_executor_wrap.rb:13:in `run'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:23:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:27:in `pass'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware.rb:19:in `pass'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/action/progress.rb:31:in `with_progress_calculation'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/action/progress.rb:17:in `run'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:23:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:27:in `pass'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware.rb:19:in `pass'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/app/lib/actions/middleware/keep_current_request_id.rb:15:in `block in run'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/app/lib/actions/middleware/keep_current_request_id.rb:49:in `restore_current_request_id'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/app/lib/actions/middleware/keep_current_request_id.rb:15:in `run'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:23:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:27:in `pass'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware.rb:19:in `pass'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/app/lib/actions/middleware/keep_current_timezone.rb:15:in `block in run'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/app/lib/actions/middleware/keep_current_timezone.rb:44:in `restore_curent_timezone'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/app/lib/actions/middleware/keep_current_timezone.rb:15:in `run'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:23:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:27:in `pass'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware.rb:19:in `pass'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/app/lib/actions/middleware/keep_current_user.rb:15:in `block in run'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/app/lib/actions/middleware/keep_current_user.rb:44:in `restore_curent_user'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/app/lib/actions/middleware/keep_current_user.rb:15:in `run'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:23:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:27:in `pass'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware.rb:19:in `pass'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/app/lib/actions/middleware/keep_current_taxonomies.rb:15:in `block in run'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/app/lib/actions/middleware/keep_current_taxonomies.rb:45:in `restore_current_taxonomies'
/usr/share/foreman/vendor/ruby/2.5.0/gems/foreman-tasks-2.0.0/app/lib/actions/middleware/keep_current_taxonomies.rb:15:in `run'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:23:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:27:in `pass'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware.rb:19:in `pass'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware.rb:32:in `run'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:23:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/middleware/world.rb:31:in `execute'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/action.rb:562:in `block (2 levels) in execute_run'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/action.rb:561:in `catch'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/action.rb:561:in `block in execute_run'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/action.rb:475:in `block in with_error_handling'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/action.rb:475:in `catch'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/action.rb:475:in `with_error_handling'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/action.rb:556:in `execute_run'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/action.rb:285:in `execute'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:18:in `block (2 levels) in execute'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/execution_plan/steps/abstract.rb:167:in `with_meta_calculation'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:17:in `block in execute'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:32:in `open_action'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:16:in `execute'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/director.rb:93:in `execute'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/executors/sidekiq/worker_jobs.rb:11:in `block (2 levels) in perform'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/executors.rb:18:in `run_user_code'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/executors/sidekiq/worker_jobs.rb:9:in `block in perform'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/executors/sidekiq/worker_jobs.rb:25:in `with_telemetry'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/executors/sidekiq/worker_jobs.rb:8:in `perform'
/usr/share/foreman/vendor/ruby/2.5.0/gems/dynflow-1.4.6/lib/dynflow/executors/sidekiq/serialization.rb:27:in `perform'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/processor.rb:192:in `execute_job'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/processor.rb:165:in `block (2 levels) in process'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/middleware/chain.rb:128:in `block in invoke'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/middleware/chain.rb:133:in `invoke'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/processor.rb:164:in `block in process'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/processor.rb:137:in `block (6 levels) in dispatch'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/job_retry.rb:109:in `local'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/processor.rb:136:in `block (5 levels) in dispatch'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq.rb:37:in `block in <module:Sidekiq>'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/processor.rb:132:in `block (4 levels) in dispatch'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/processor.rb:250:in `stats'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/processor.rb:127:in `block (3 levels) in dispatch'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/job_logger.rb:8:in `call'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/processor.rb:126:in `block (2 levels) in dispatch'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/job_retry.rb:74:in `global'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/processor.rb:125:in `block in dispatch'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/logging.rb:48:in `with_context'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/logging.rb:42:in `with_job_hash_context'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/processor.rb:124:in `dispatch'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/processor.rb:163:in `process'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/processor.rb:83:in `process_one'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/processor.rb:71:in `run'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/util.rb:16:in `watchdog'
/usr/share/foreman/vendor/ruby/2.5.0/gems/sidekiq-5.2.9/lib/sidekiq/util.rb:25:in `block in safe_thread'
/usr/share/foreman/vendor/ruby/2.5.0/gems/logging-2.2.2/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'

aruzicka · July 20, 2020, 2:16pm

When you run a rex job, the actual execution gets delegated to the smart proxy. Smart proxy runs the job and when it is done it tries to call back to foreman. If foreman doesn’t hear back from the proxy within 10 minutes, it checks on it. What most likely is happening is that the callback isn’t going through for some reason and then job is marked as failed when foreman checks up on the proxy and finds out about it.

With that being said, if your foreman url is set correctly, you should find something about the callback either in nginx’s logs or foremans logs, depending where it breaks.