Remote execution help

Problem:
I am trying to run a simple echo hi or cat /etc/hosts command from foreman web UI. I am getting the following errro in foreman_tasks section:

Failed to initialize: Dynflow::ExecutionPlan::Steps::Error - ERF42-3837 [Foreman::Exception]: The smart proxy task b38453f0-06e2-44a9-9346-4b84deecda38 failed.
Error initializing command: IOError - closed stream

Errors:

ERF42-3837 [Foreman::Exception]: The smart proxy task b38453f0-06e2-44a9-9346-4b84deecda38 failed.

Ruby is kind of Greek to me and any help would be appreciated.

Note that I installed all the packages required for remote execution as per Foreman :: Plugin Manuals as I already had existing foreman installation. I created SSH keys as mentioned and copied that to my client.

Expected outcome:
Remote exeuction should work.

Foreman and Proxy versions:

[root@foremankatellodemo .ssh]# rpm -qa | grep foreman
tfm-rubygem-hammer_cli_foreman_docker-0.0.4-2.el7.noarch
foremankatellodemo.example.com-foreman-client-1.0-1.noarch
foremankatellodemo.example.com-puppet-client-1.0-1.noarch
tfm-rubygem-hammer_cli_foreman-0.10.2-1.el7.noarch
foremankatellodemo.example.com-foreman-proxy-client-1.0-1.noarch
foreman-debug-1.15.6-1.el7.noarch
foreman-selinux-1.15.6-1.el7.noarch
foreman-1.15.6-1.el7.noarch
foreman-postgresql-1.15.6-1.el7.noarch
tfm-rubygem-hammer_cli_foreman_bootdisk-0.1.3-5.el7.noarch
foremankatellodemo.example.com-qpid-router-server-1.0-1.noarch
foremankatellodemo.example.com-tomcat-1.0-1.noarch
tfm-rubygem-foreman_remote_execution_core-1.0.6-1.fm1_15.el7.noarch
foreman-installer-1.15.6-2.el7.noarch
foreman-release-scl-3-1.el7.noarch
tfm-rubygem-foreman-tasks-core-0.1.8-1.fm1_15.el7.noarch
foreman-compute-1.15.6-1.el7.noarch
tfm-rubygem-hammer_cli_foreman_tasks-0.0.12-1.fm1_15.el7.noarch
foremankatellodemo.example.com-apache-1.0-1.noarch
foremankatellodemo.example.com-qpid-router-client-1.0-1.noarch
foreman-cli-1.15.6-1.el7.noarch
foremankatellodemo.example.com-qpid-client-cert-1.0-1.noarch
tfm-rubygem-foreman_remote_execution-1.3.7-1.fm1_15.el7.noarch
tfm-rubygem-foreman_docker-3.2.1-1.fm1_15.el7.noarch
foremankatellodemo.example.com-foreman-proxy-1.0-1.noarch
foremankatellodemo.example.com-qpid-broker-1.0-1.noarch
foreman-proxy-1.15.6-1.el7.noarch
foreman-installer-katello-3.4.5-1.el7.noarch
tfm-rubygem-foreman-tasks-0.9.6-1.fm1_15.el7.noarch
foreman-release-1.15.6-1.el7.noarch
[root@foremankatellodemo .ssh]# 

Foreman and Proxy plugin versions:

[root@foremankatellodemo .ssh]# foreman-rake plugin:list
Collecting plugin information
Foreman plugin: bastion, 5.1.1, Eric D Helms and Walden Raines, Bastion provides a UI library of AngularJS based components designed to integrate and work with Foreman.
Foreman plugin: foreman-tasks, 0.9.6, Ivan NeÄŤas, The goal of this plugin is to unify the way of showing task statuses across the Foreman instance.
It defines Task model for keeping the information about the tasks and Lock for assigning the tasks
to resources. The locking allows dealing with preventing multiple colliding tasks to be run on the
same resource. It also optionally provides Dynflow infrastructure for using it for managing the tasks.
Foreman plugin: foreman_docker, 3.2.1, Daniel Lobato, Amos Benari, Provision and manage Docker containers and images from Foreman.
Foreman plugin: foreman_remote_execution, 1.3.7, Foreman Remote Execution team, A plugin bringing remote execution to the Foreman, completing the config management functionality with remote management functionality.
Foreman plugin: katello, 3.4.5, N/A, Content and Subscription Management plugin for Foreman
[root@foremankatellodemo .ssh]# 

Other relevant data:
Cannot put production.log in this post. That’s coming.

Any help is appreciated. Thanks folks.

production_log.tar.gz (6.7 KB)

File attached.

Hello,
thanks for letting us know. From Error initializing command: IOError - closed stream it seems something went wrong on Smart Proxy’s side. To be able to dig deeper into this, we’d need logs from the Smart Proxy, namely /var/log/foreman-proxy/proxy.log and /var/log/foreman-proxy/smart_proxy_dynflow_core.log.

I quickly skimmed over the attached production.log but haven’t found out anything helpful. Having logs from the proxy should help us move forward.

Hello,

[root@foremankatellodemo ~]# tailf /var/log/foreman-proxy/proxy.log


I, [2018-03-01T08:25:18.199162 ]  INFO -- : 127.0.0.1 - - [01/Mar/2018:08:25:18 +0000] "GET /dynflow/tasks/count?state=running HTTP/1.1" 200 29 0.1872

I, [2018-03-01T08:25:19.547981 ]  INFO -- : 127.0.0.1 - - [01/Mar/2018:08:25:19 +0000] "POST /dynflow/tasks/ HTTP/1.1" 200 50 0.0316

I, [2018-03-01T08:26:19.533353 ]  INFO -- : 127.0.0.1 - - [01/Mar/2018:08:26:19 +0000] "GET /dynflow/tasks/7cddd5d6-777e-4766-bfb9-a2001530f0b3/status HTTP/1.1" 200 2332 0.0140

I, [2018-03-01T08:26:58.804524 ]  INFO -- : 127.0.0.1 - - [01/Mar/2018:08:26:58 +0000] "GET /dynflow/tasks/7cddd5d6-777e-4766-bfb9-a2001530f0b3/status HTTP/1.1" 200 2332 0.0135
[root@foremankatellodemo foreman-proxy]# cat /var/log/foreman-proxy/smart_proxy_dynflow_core.log
[root@foremankatellodemo foreman-proxy]# wc -l /var/log/foreman-proxy/smart_proxy_dynflow_core.log
0 /var/log/foreman-proxy/smart_proxy_dynflow_core.log
[root@foremankatellodemo foreman-proxy]# 

Doesn’t look very promising. I will try to enable debug logging and let you know. If I can’t find way to generate debug logging, please tell me what parameters shall I tweak and what you would need.

So I enabled debug log but not much help from there as well:

[root@foremankatellodemo foreman-proxy]# grep -i log_level /etc/foreman-proxy/settings.yml 
:log_level: DEBUG
[root@foremankatellodemo foreman-proxy]# 

And here are the logs:

D, [2018-03-01T08:34:37.046829 ] DEBUG -- : accept: 127.0.0.1:56450
D, [2018-03-01T08:34:37.048652 ] DEBUG -- : Rack::Handler::WEBrick is invoked.
D, [2018-03-01T08:34:37.057412 ] DEBUG -- : Proxy request from foremankatellodemo.example.com:9090/dynflow/tasks/count to http://127.0.0.1:8008/tasks/count
D, [2018-03-01T08:34:37.063515 ] DEBUG -- : Proxy request status 200 - #<Net::HTTPOK:0x00000002bb3788>
I, [2018-03-01T08:34:37.064965 ]  INFO -- : 127.0.0.1 - - [01/Mar/2018:08:34:37 +0000] "GET /dynflow/tasks/count?state=running HTTP/1.1" 200 29 0.0093

D, [2018-03-01T08:34:37.109544 ] DEBUG -- : close: 127.0.0.1:56450
D, [2018-03-01T08:34:38.432372 ] DEBUG -- : accept: 127.0.0.1:56454
D, [2018-03-01T08:34:38.438610 ] DEBUG -- : Rack::Handler::WEBrick is invoked.
D, [2018-03-01T08:34:38.439615 ] DEBUG -- : Proxy request from foremankatellodemo.example.com:9090/dynflow/tasks/ to http://127.0.0.1:8008/tasks/
D, [2018-03-01T08:34:38.470944 ] DEBUG -- : Proxy request status 200 - #<Net::HTTPOK:0x00000002c2c4a8>
I, [2018-03-01T08:34:38.471323 ]  INFO -- : 127.0.0.1 - - [01/Mar/2018:08:34:38 +0000] "POST /dynflow/tasks/ HTTP/1.1" 200 50 0.0320

D, [2018-03-01T08:34:38.512275 ] DEBUG -- : close: 127.0.0.1:56454
D, [2018-03-01T08:35:38.445590 ] DEBUG -- : accept: 127.0.0.1:56488
D, [2018-03-01T08:35:38.449524 ] DEBUG -- : Rack::Handler::WEBrick is invoked.
D, [2018-03-01T08:35:38.451018 ] DEBUG -- : Proxy request from foremankatellodemo.example.com:9090/dynflow/tasks/9e5ded5d-56ec-49a9-9b6a-6b74fd9a1439/status to http://127.0.0.1:8008/tasks/9e5ded5d-56ec-49a9-9b6a-6b74fd9a1439/status
D, [2018-03-01T08:35:38.464560 ] DEBUG -- : Proxy request status 200 - #<Net::HTTPOK:0x00000002cc7f98>
I, [2018-03-01T08:35:38.465019 ]  INFO -- : 127.0.0.1 - - [01/Mar/2018:08:35:38 +0000] "GET /dynflow/tasks/9e5ded5d-56ec-49a9-9b6a-6b74fd9a1439/status HTTP/1.1" 200 2330 0.0144

D, [2018-03-01T08:35:38.507326 ] DEBUG -- : close: 127.0.0.1:56488
D, [2018-03-01T08:36:09.848956 ] DEBUG -- : accept: 127.0.0.1:56508
D, [2018-03-01T08:36:09.852649 ] DEBUG -- : Rack::Handler::WEBrick is invoked.
D, [2018-03-01T08:36:09.853881 ] DEBUG -- : Proxy request from foremankatellodemo.example.com:9090/dynflow/tasks/9e5ded5d-56ec-49a9-9b6a-6b74fd9a1439/status to http://127.0.0.1:8008/tasks/9e5ded5d-56ec-49a9-9b6a-6b74fd9a1439/status
D, [2018-03-01T08:36:09.864700 ] DEBUG -- : Proxy request status 200 - #<Net::HTTPOK:0x00000002d1ac98>
I, [2018-03-01T08:36:09.865204 ]  INFO -- : 127.0.0.1 - - [01/Mar/2018:08:36:09 +0000] "GET /dynflow/tasks/9e5ded5d-56ec-49a9-9b6a-6b74fd9a1439/status HTTP/1.1" 200 2330 0.0116

D, [2018-03-01T08:36:09.919015 ] DEBUG -- : close: 127.0.0.1:56508

Smart_proxy_dynflow_core is still empty:

[root@foremankatellodemo foreman-proxy]# cat smart_proxy_dynflow_core.log
[root@foremankatellodemo foreman-proxy]#

Try setting :log_level: to DEBUG in /etc/smart_proxy_dynflow_core/settings.yml and restarting the smart_proxy_dynflow_core service.

Having empty logs is odd, weren’t the logfiles rotated?

Thanks. The problem was in the config file.

# File to log to, leave empty for logging to STDOUT
# :log_file: /var/log/foreman-proxy/smart_proxy_dynflow_core.log

# Log level, one of UNKNOWN, FATAL, ERROR, WARN, INFO, DEBUG
# :log_level: ERROR

See that :log_level: ERROR is commented out. This is vanilla installation btw with foreman-installer.

I changed this to :log_level: DEBUG and restarted.

[root@foremankatellodemo smart_proxy_dynflow_core]# vi settings.yml
[root@foremankatellodemo smart_proxy_dynflow_core]# systemctl status smart_proxy_dynflow_core
â—Ź smart_proxy_dynflow_core.service - Foreman smart proxy dynflow core service
   Loaded: loaded (/usr/lib/systemd/system/smart_proxy_dynflow_core.service; disabled; vendor preset: disabled)
   Active: active (running) since Thu 2018-03-01 08:10:33 UTC; 32min ago
     Docs: https://github.com/theforeman/smart_proxy_dynflow
  Process: 5842 ExecStart=/usr/bin/smart_proxy_dynflow_core -d -p /var/run/foreman-proxy/smart_proxy_dynflow_core.pid (code=exited, status=0/SUCCESS)
 Main PID: 5872 (ruby)
   CGroup: /system.slice/smart_proxy_dynflow_core.service
           └─5872 ruby /usr/bin/smart_proxy_dynflow_core -d -p /var/run/foreman-proxy/smart_proxy_dynflow_core.pid

Mar 01 08:10:32 foremankatellodemo.example.com systemd[1]: Starting Foreman smart proxy dynflow core service...
Mar 01 08:10:33 foremankatellodemo.example.com systemd[1]: Started Foreman smart proxy dynflow core service.
[root@foremankatellodemo smart_proxy_dynflow_core]# systemctl restart smart_proxy_dynflow_core
[root@foremankatellodemo smart_proxy_dynflow_core]# grep -i log_level settings.yml 
:log_level: DEBUG
[root@foremankatellodemo smart_proxy_dynflow_core]# 

And now I see logs in smart_proxy_dynflow_core:

[root@foremankatellodemo foreman-proxy]# cat smart_proxy_dynflow_core.log
D, [2018-03-01T08:42:46.293662 #9004] DEBUG -- : Using HTTP
I, [2018-03-01T08:42:46.302867 #9009]  INFO -- : WEBrick 1.3.1
I, [2018-03-01T08:42:46.302966 #9009]  INFO -- : ruby 2.2.2 (2015-04-13) [x86_64-linux]
D, [2018-03-01T08:42:46.303521 #9009] DEBUG -- : Rack::Handler::WEBrick is mounted on /.
I, [2018-03-01T08:42:46.303622 #9009]  INFO -- : WEBrick::HTTPServer#start: pid=9009 port=8008
D, [2018-03-01T08:43:27.184344 #9009] DEBUG -- : accept: 127.0.0.1:55420
D, [2018-03-01T08:43:27.186418 #9009] DEBUG -- : Rack::Handler::WEBrick is invoked.
[2018-03-01 08:43:27.197 #9009]  WARN -- Could not open DB for dynflow at '', will keep data in memory. Restart will drop all dynflow data.
[2018-03-01 08:43:27.302 #9009]  INFO -- dynflow: Execution plan cleaner removing 0 execution plans.
[2018-03-01 08:43:27.312 #9009] DEBUG -- require_ssl_client_verification: skipping, non-HTTPS request
foremankatellodemo.example.com - - [01/Mar/2018:08:43:27 UTC] "GET /tasks/count?state=running HTTP/1.1" 200 29
[2018-03-01 08:43:27.319 #9009] DEBUG -- close: 127.0.0.1:55420
[2018-03-01 08:43:27.602 #9009] DEBUG -- accept: 127.0.0.1:55424
[2018-03-01 08:43:27.604 #9009] DEBUG -- Rack::Handler::WEBrick is invoked.
[2018-03-01 08:43:27.604 #9009] DEBUG -- require_ssl_client_verification: skipping, non-HTTPS request
[2018-03-01 08:43:27.607 #9009] DEBUG -- dynflow: ExecutionPlan ff2851bd-3e43-4d90-b8a7-d093a6f1bea0      pending >>  planning
[2018-03-01 08:43:27.608 #9009] DEBUG -- dynflow:          Step ff2851bd-3e43-4d90-b8a7-d093a6f1bea0: 1   pending >>   running in phase     Plan ForemanRemoteExecutionCore::Actions::RunScript
[2018-03-01 08:43:27.610 #9009] DEBUG -- dynflow:          Step ff2851bd-3e43-4d90-b8a7-d093a6f1bea0: 4   pending >>   running in phase     Plan SmartProxyDynflowCore::Callback::Action
[2018-03-01 08:43:27.612 #9009] DEBUG -- dynflow:          Step ff2851bd-3e43-4d90-b8a7-d093a6f1bea0: 4   running >>   success in phase     Plan SmartProxyDynflowCore::Callback::Action
[2018-03-01 08:43:27.612 #9009] DEBUG -- dynflow:          Step ff2851bd-3e43-4d90-b8a7-d093a6f1bea0: 1   running >>   success in phase     Plan ForemanRemoteExecutionCore::Actions::RunScript
[2018-03-01 08:43:27.618 #9009] DEBUG -- dynflow: ExecutionPlan ff2851bd-3e43-4d90-b8a7-d093a6f1bea0     planning >>   planned
[2018-03-01 08:43:27.622 #9009] DEBUG -- dynflow: ExecutionPlan ff2851bd-3e43-4d90-b8a7-d093a6f1bea0      planned >>   running
[2018-03-01 08:43:27.624 #9009] DEBUG -- dynflow:          Step ff2851bd-3e43-4d90-b8a7-d093a6f1bea0: 2   pending >>   running in phase      Run ForemanRemoteExecutionCore::Actions::RunScript
[2018-03-01 08:43:27.626 #9009] DEBUG -- dynflow:          Step ff2851bd-3e43-4d90-b8a7-d093a6f1bea0: 2   running >> suspended in phase      Run ForemanRemoteExecutionCore::Actions::RunScript
[2018-03-01 08:43:27.628 #9009] DEBUG -- dynflow: start runner 1e98c84c-5bd5-45ba-9705-b5a82d4eafaf
[2018-03-01 08:43:27.628 #9009] DEBUG -- dynflow: opening session to root@foremanclient7dev.example.com
foremankatellodemo.example.com - - [01/Mar/2018:08:43:27 UTC] "POST /tasks/ HTTP/1.1" 200 50
[2018-03-01 08:43:27.630 #9009] DEBUG -- close: 127.0.0.1:55424
[2018-03-01 08:43:27.741 #9009] ERROR -- dynflow: error while initalizing command IOError closed stream:
 /opt/theforeman/tfm/root/usr/share/gems/gems/net-ssh-4.0.1/lib/net/ssh/transport/session.rb:128:in `close'
/opt/theforeman/tfm/root/usr/share/gems/gems/net-ssh-4.0.1/lib/net/ssh/transport/session.rb:128:in `close'
/opt/theforeman/tfm/root/usr/share/gems/gems/net-ssh-4.0.1/lib/net/ssh.rb:253:in `rescue in start'
/opt/theforeman/tfm/root/usr/share/gems/gems/net-ssh-4.0.1/lib/net/ssh.rb:205:in `start'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_remote_execution_core-1.0.6/lib/foreman_remote_execution_core/script_runner.rb:134:in `session'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_remote_execution_core-1.0.6/lib/foreman_remote_execution_core/script_runner.rb:191:in `run_sync'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_remote_execution_core-1.0.6/lib/foreman_remote_execution_core/script_runner.rb:288:in `ensure_remote_directory'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_remote_execution_core-1.0.6/lib/foreman_remote_execution_core/script_runner.rb:265:in `upload_data'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_remote_execution_core-1.0.6/lib/foreman_remote_execution_core/script_runner.rb:261:in `cp_script_to_remote'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_remote_execution_core-1.0.6/lib/foreman_remote_execution_core/script_runner.rb:48:in `prepare_start'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_remote_execution_core-1.0.6/lib/foreman_remote_execution_core/script_runner.rb:34:in `start'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-core-0.1.8/lib/foreman_tasks_core/runner/dispatcher.rb:32:in `start_runner'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.34/lib/dynflow/actor.rb:6:in `on_message'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/context.rb:46:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-core-0.1.8/lib/foreman_tasks_core/runner/dispatcher.rb:24:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/executes_context.rb:7:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.34/lib/dynflow/actor.rb:26:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/awaits.rb:15:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/sets_results.rb:14:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/buffer.rb:38:in `process_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/buffer.rb:31:in `process_envelopes?'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/buffer.rb:20:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/termination.rb:55:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/removes_child.rb:10:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/sets_results.rb:14:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/core.rb:161:in `process_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/core.rb:95:in `block in on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/core.rb:118:in `block (2 levels) in schedule_execution'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.3/lib/concurrent/synchronization/mri_lockable_object.rb:38:in `block in synchronize'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.3/lib/concurrent/synchronization/mri_lockable_object.rb:38:in `synchronize'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.3/lib/concurrent/synchronization/mri_lockable_object.rb:38:in `synchronize'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/core.rb:115:in `block in schedule_execution'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.3/lib/concurrent/executor/serialized_execution.rb:18:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.3/lib/concurrent/executor/serialized_execution.rb:18:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.3/lib/concurrent/executor/serialized_execution.rb:96:in `work'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.3/lib/concurrent/executor/serialized_execution.rb:77:in `block in call_job'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.3/lib/concurrent/executor/ruby_thread_pool_executor.rb:348:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.3/lib/concurrent/executor/ruby_thread_pool_executor.rb:348:in `run_task'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.3/lib/concurrent/executor/ruby_thread_pool_executor.rb:337:in `block (3 levels) in create_worker'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.3/lib/concurrent/executor/ruby_thread_pool_executor.rb:320:in `loop'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.3/lib/concurrent/executor/ruby_thread_pool_executor.rb:320:in `block (2 levels) in create_worker'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.3/lib/concurrent/executor/ruby_thread_pool_executor.rb:319:in `catch'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.3/lib/concurrent/executor/ruby_thread_pool_executor.rb:319:in `block in create_worker'
[2018-03-01 08:43:27.742 #9009] ERROR -- dynflow: Error initializing command - IOError closed stream:
/opt/theforeman/tfm/root/usr/share/gems/gems/net-ssh-4.0.1/lib/net/ssh/transport/session.rb:128:in `close'
/opt/theforeman/tfm/root/usr/share/gems/gems/net-ssh-4.0.1/lib/net/ssh/transport/session.rb:128:in `close'
/opt/theforeman/tfm/root/usr/share/gems/gems/net-ssh-4.0.1/lib/net/ssh.rb:253:in `rescue in start'
/opt/theforeman/tfm/root/usr/share/gems/gems/net-ssh-4.0.1/lib/net/ssh.rb:205:in `start'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_remote_execution_core-1.0.6/lib/foreman_remote_execution_core/script_runner.rb:134:in `session'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_remote_execution_core-1.0.6/lib/foreman_remote_execution_core/script_runner.rb:191:in `run_sync'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_remote_execution_core-1.0.6/lib/foreman_remote_execution_core/script_runner.rb:288:in `ensure_remote_directory'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_remote_execution_core-1.0.6/lib/foreman_remote_execution_core/script_runner.rb:265:in `upload_data'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_remote_execution_core-1.0.6/lib/foreman_remote_execution_core/script_runner.rb:261:in `cp_script_to_remote'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_remote_execution_core-1.0.6/lib/foreman_remote_execution_core/script_runner.rb:48:in `prepare_start'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman_remote_execution_core-1.0.6/lib/foreman_remote_execution_core/script_runner.rb:34:in `start'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-core-0.1.8/lib/foreman_tasks_core/runner/dispatcher.rb:32:in `start_runner'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.34/lib/dynflow/actor.rb:6:in `on_message'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/context.rb:46:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-core-0.1.8/lib/foreman_tasks_core/runner/dispatcher.rb:24:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/executes_context.rb:7:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.34/lib/dynflow/actor.rb:26:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/awaits.rb:15:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/sets_results.rb:14:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/buffer.rb:38:in `process_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/buffer.rb:31:in `process_envelopes?'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/buffer.rb:20:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/termination.rb:55:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/removes_child.rb:10:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/sets_results.rb:14:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/core.rb:161:in `process_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/core.rb:95:in `block in on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/core.rb:118:in `block (2 levels) in schedule_execution'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.3/lib/concurrent/synchronization/mri_lockable_object.rb:38:in `block in synchronize'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.3/lib/concurrent/synchronization/mri_lockable_object.rb:38:in `synchronize'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.3/lib/concurrent/synchronization/mri_lockable_object.rb:38:in `synchronize'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/core.rb:115:in `block in schedule_execution'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.3/lib/concurrent/executor/serialized_execution.rb:18:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.3/lib/concurrent/executor/serialized_execution.rb:18:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.3/lib/concurrent/executor/serialized_execution.rb:96:in `work'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.3/lib/concurrent/executor/serialized_execution.rb:77:in `block in call_job'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.3/lib/concurrent/executor/ruby_thread_pool_executor.rb:348:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.3/lib/concurrent/executor/ruby_thread_pool_executor.rb:348:in `run_task'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.3/lib/concurrent/executor/ruby_thread_pool_executor.rb:337:in `block (3 levels) in create_worker'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.3/lib/concurrent/executor/ruby_thread_pool_executor.rb:320:in `loop'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.3/lib/concurrent/executor/ruby_thread_pool_executor.rb:320:in `block (2 levels) in create_worker'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.3/lib/concurrent/executor/ruby_thread_pool_executor.rb:319:in `catch'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.3/lib/concurrent/executor/ruby_thread_pool_executor.rb:319:in `block in create_worker'
[2018-03-01 08:43:27.742 #9009] DEBUG -- dynflow: refresh runner 1e98c84c-5bd5-45ba-9705-b5a82d4eafaf
[2018-03-01 08:43:27.742 #9009] DEBUG -- dynflow: refreshing runner
[2018-03-01 08:43:27.742 #9009] DEBUG -- dynflow: finish runner 1e98c84c-5bd5-45ba-9705-b5a82d4eafaf
[2018-03-01 08:43:27.742 #9009] DEBUG -- dynflow: closing session for command [1e98c84c-5bd5-45ba-9705-b5a82d4eafaf],0 actors left 
[2018-03-01 08:43:27.743 #9009] DEBUG -- dynflow: terminate 1e98c84c-5bd5-45ba-9705-b5a82d4eafaf
[2018-03-01 08:43:27.745 #9009] DEBUG -- dynflow:          Step ff2851bd-3e43-4d90-b8a7-d093a6f1bea0: 2 got event #<ForemanTasksCore::Runner::Update:0x000000027dba70>
[2018-03-01 08:43:27.745 #9009] DEBUG -- dynflow:          Step ff2851bd-3e43-4d90-b8a7-d093a6f1bea0: 2 suspended >>   running in phase      Run ForemanRemoteExecutionCore::Actions::RunScript
[2018-03-01 08:43:27.747 #9009] DEBUG -- dynflow:          Step ff2851bd-3e43-4d90-b8a7-d093a6f1bea0: 2   running >>   success in phase      Run ForemanRemoteExecutionCore::Actions::RunScript
[2018-03-01 08:43:27.750 #9009] DEBUG -- dynflow:          Step ff2851bd-3e43-4d90-b8a7-d093a6f1bea0: 5   pending >>   running in phase      Run SmartProxyDynflowCore::Callback::Action
[2018-03-01 08:43:27.760 #9009] ERROR --  action: Connection refused - connect(2) for "localhost" port 3000 (Errno::ECONNREFUSED)
/opt/rh/rh-ruby22/root/usr/share/ruby/net/http.rb:879:in `initialize'
/opt/rh/rh-ruby22/root/usr/share/ruby/net/http.rb:879:in `open'
/opt/rh/rh-ruby22/root/usr/share/ruby/net/http.rb:879:in `block in connect'
/opt/rh/rh-ruby22/root/usr/share/ruby/timeout.rb:74:in `timeout'
/opt/rh/rh-ruby22/root/usr/share/ruby/net/http.rb:878:in `connect'
/opt/rh/rh-ruby22/root/usr/share/ruby/net/http.rb:863:in `do_start'
/opt/rh/rh-ruby22/root/usr/share/ruby/net/http.rb:852:in `start'
/opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-1.8.0/lib/restclient/request.rb:413:in `transmit'
/opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-1.8.0/lib/restclient/request.rb:176:in `execute'
/opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-1.8.0/lib/restclient/request.rb:41:in `execute'
/opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-1.8.0/lib/restclient/resource.rb:67:in `post'
/opt/theforeman/tfm/root/usr/share/gems/gems/smart_proxy_dynflow_core-0.1.8/lib/smart_proxy_dynflow_core/callback.rb:22:in `callback'
/opt/theforeman/tfm/root/usr/share/gems/gems/smart_proxy_dynflow_core-0.1.8/lib/smart_proxy_dynflow_core/callback.rb:30:in `send_to_foreman_tasks'
/opt/theforeman/tfm/root/usr/share/gems/gems/smart_proxy_dynflow_core-0.1.8/lib/smart_proxy_dynflow_core/callback.rb:74:in `run'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.34/lib/dynflow/action.rb:518:in `block (3 levels) in execute_run'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.34/lib/dynflow/middleware/stack.rb:26:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.34/lib/dynflow/middleware/stack.rb:26:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.34/lib/dynflow/middleware.rb:18:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.34/lib/dynflow/action/progress.rb:30:in `with_progress_calculation'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.34/lib/dynflow/action/progress.rb:16:in `run'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.34/lib/dynflow/middleware/stack.rb:22:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.34/lib/dynflow/middleware/stack.rb:26:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.34/lib/dynflow/middleware.rb:18:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.34/lib/dynflow/middleware.rb:31:in `run'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.34/lib/dynflow/middleware/stack.rb:22:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.34/lib/dynflow/middleware/world.rb:30:in `execute'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.34/lib/dynflow/action.rb:517:in `block (2 levels) in execute_run'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.34/lib/dynflow/action.rb:516:in `catch'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.34/lib/dynflow/action.rb:516:in `block in execute_run'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.34/lib/dynflow/action.rb:431:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.34/lib/dynflow/action.rb:431:in `block in with_error_handling'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.34/lib/dynflow/action.rb:431:in `catch'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.34/lib/dynflow/action.rb:431:in `with_error_handling'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.34/lib/dynflow/action.rb:511:in `execute_run'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.34/lib/dynflow/action.rb:268:in `execute'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.34/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:9:in `block (2 levels) in execute'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.34/lib/dynflow/execution_plan/steps/abstract.rb:155:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.34/lib/dynflow/execution_plan/steps/abstract.rb:155:in `with_meta_calculation'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.34/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:8:in `block in execute'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.34/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:22:in `open_action'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.34/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:7:in `execute'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.34/lib/dynflow/director.rb:42:in `execute'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.34/lib/dynflow/executors/parallel/worker.rb:11:in `on_message'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/context.rb:46:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/executes_context.rb:7:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.34/lib/dynflow/actor.rb:26:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/awaits.rb:15:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/sets_results.rb:14:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/buffer.rb:38:in `process_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/buffer.rb:31:in `process_envelopes?'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/buffer.rb:20:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/termination.rb:55:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/removes_child.rb:10:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/behaviour/sets_results.rb:14:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/core.rb:161:in `process_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/core.rb:95:in `block in on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/core.rb:118:in `block (2 levels) in schedule_execution'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.3/lib/concurrent/synchronization/mri_lockable_object.rb:38:in `block in synchronize'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.3/lib/concurrent/synchronization/mri_lockable_object.rb:38:in `synchronize'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.3/lib/concurrent/synchronization/mri_lockable_object.rb:38:in `synchronize'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.3/lib/concurrent/actor/core.rb:115:in `block in schedule_execution'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.3/lib/concurrent/executor/serialized_execution.rb:18:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.3/lib/concurrent/executor/serialized_execution.rb:18:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.3/lib/concurrent/executor/serialized_execution.rb:96:in `work'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.3/lib/concurrent/executor/serialized_execution.rb:77:in `block in call_job'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.3/lib/concurrent/executor/ruby_thread_pool_executor.rb:348:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.3/lib/concurrent/executor/ruby_thread_pool_executor.rb:348:in `run_task'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.3/lib/concurrent/executor/ruby_thread_pool_executor.rb:337:in `block (3 levels) in create_worker'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.3/lib/concurrent/executor/ruby_thread_pool_executor.rb:320:in `loop'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.3/lib/concurrent/executor/ruby_thread_pool_executor.rb:320:in `block (2 levels) in create_worker'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.3/lib/concurrent/executor/ruby_thread_pool_executor.rb:319:in `catch'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.3/lib/concurrent/executor/ruby_thread_pool_executor.rb:319:in `block in create_worker'
[2018-03-01 08:43:27.760 #9009] DEBUG -- dynflow:          Step ff2851bd-3e43-4d90-b8a7-d093a6f1bea0: 5   running >>     error in phase      Run SmartProxyDynflowCore::Callback::Action
[2018-03-01 08:43:27.764 #9009] DEBUG -- dynflow: ExecutionPlan ff2851bd-3e43-4d90-b8a7-d093a6f1bea0      running >>    paused
[2018-03-01 08:44:27.616 #9009] DEBUG -- accept: 127.0.0.1:55474
[2018-03-01 08:44:27.619 #9009] DEBUG -- Rack::Handler::WEBrick is invoked.
[2018-03-01 08:44:27.620 #9009] DEBUG -- require_ssl_client_verification: skipping, non-HTTPS request
foremankatellodemo.example.com - - [01/Mar/2018:08:44:27 UTC] "GET /tasks/ff2851bd-3e43-4d90-b8a7-d093a6f1bea0/status? HTTP/1.1" 200 2332
[2018-03-01 08:44:27.627 #9009] DEBUG -- close: 127.0.0.1:55474
[root@foremankatellodemo foreman-proxy]#

Excellent, now we’re getting somewhere. It looks you’re not the first one who encountered this issue. Could you please try steps described in this message[1] and let us know if it solves your problem?

[1] - https://groups.google.com/d/msg/foreman-users/rWGWQ58GYag/0obirhy_AwAJ

1 Like

Let me see, Adam. Not a ruby guy myself so lol…not so sure. But FWIW, let me give it a try. I will give you an update soon.

BTW: Do you want me to file a redmine issue? Also shall the smart_proxy_dynflow_core should have a commented out log_level?

The important part is adding the identity to the ssh-agent, so no ruby knowledge is required :slight_smile:

$ sudo -u foreman-proxy ssh-agent bash
bash-4.2$ ssh-add /usr/share/foreman-proxy/.ssh/id_rsa_foreman_proxy

No need to, apparently we already have an issue filed which matches what we saw in your logs.
http://projects.theforeman.org/issues/21673

By default the option is commented out and a default value (ERROR) is used. It can be uncommented and changed by the user when needed.

1 Like

Thanks Adam. You are a hero :slight_smile:

So I did everything but apparently something is failing me somewhere. Take a look at the following code block where I added the identity to ssh-agent but on next log out, it wipes the identity, which I think is expected. But it still asks me to enter password. Here I should say that I am doing this on my local vagrant environment and so maybe there is some SSH quirk hidden at some level.

[root@foremankatellodemo smart_proxy_dynflow_core]# pwd
/etc/smart_proxy_dynflow_core
[root@foremankatellodemo smart_proxy_dynflow_core]# sudo -u foreman-proxy ssh-agent bash
bash-4.2$ ssh-add -l
The agent has no identities.
bash-4.2$ ssh-add /usr/share/foreman-proxy/.ssh/id_rsa_foreman_proxy
Identity added: /usr/share/foreman-proxy/.ssh/id_rsa_foreman_proxy (/usr/share/foreman-proxy/.ssh/id_rsa_foreman_proxy)
bash-4.2$ ssh-add -l
2048 SHA256:/NfxdTVwsZ2nC8gDFI4BhLQXL4LWBU76zxPNesKtpKU /usr/share/foreman-proxy/.ssh/id_rsa_foreman_proxy (RSA)
bash-4.2$ 
bash-4.2$ pwd
/etc/smart_proxy_dynflow_core
bash-4.2$ whoami
foreman-proxy
bash-4.2$ exit
[root@foremankatellodemo smart_proxy_dynflow_core]# ls
settings.yml
[root@foremankatellodemo smart_proxy_dynflow_core]# pwd
/etc/smart_proxy_dynflow_core

No ssh identity now:

[root@foremankatellodemo smart_proxy_dynflow_core]# sudo -u foreman-proxy ssh-agent bash
bash-4.2$ ssh-add -l
The agent has no identities.
bash-4.2$ exit

Try to SSH manually:

[root@foremankatellodemo smart_proxy_dynflow_core]# sudo -u foreman-proxy ssh -i ~foreman-proxy/.ssh/id_rsa_foreman_proxy root@192.168.10.30
root@192.168.10.30's password: 
Last login: Thu Mar  1 10:12:47 2018 from 192.168.10.10
[root@foremanclient7dev ~]# logout
Connection to 192.168.10.30 closed.
[root@foremankatellodemo smart_proxy_dynflow_core]# sudo -u foreman-proxy ssh-agent bash
bash-4.2$ ssh-add /usr/share/foreman-proxy/.ssh/id_rsa_foreman_proxy
Identity added: /usr/share/foreman-proxy/.ssh/id_rsa_foreman_proxy (/usr/share/foreman-proxy/.ssh/id_rsa_foreman_proxy)
bash-4.2$ sudo -u foreman-proxy ssh -i ~foreman-proxy/.ssh/id_rsa_foreman_proxy root@192.168.10.30
Sorry, user foreman-proxy is not allowed to execute '/bin/ssh -i /usr/share/foreman-proxy/.ssh/id_rsa_foreman_proxy root@192.168.10.30' as foreman-proxy on foremankatellodemo.example.com.
bash-4.2$ ssh -i ~foreman-proxy/.ssh/id_rsa_foreman_proxy root@192.168.10.30
root@192.168.10.30's password: 
Last login: Thu Mar  1 10:19:21 2018 from 192.168.10.10
[root@foremanclient7dev ~]# logout

Could this be something related with the way vagrant handles SSH?

Also much thanks for answering the other questions.

I’m failing to reproduce the issue, which makes fixing it difficult. Any progress on your side?

I can’t say, I never dealt with vagrant all that much.

I haven’t looked into this last we spoke. I will try to test it out later today again.

If I may ask, how do you reproduce this kind of issues? What I mean is that what platform do you use for this kind of debugging? I am plainly curious.

If my tests fail again, I will give you a rundown of what steps I took from the beginning so that when I actually deploy this on production I can do that confidently.

FYI (not sure if this helps the discussion), forklift was using vagrant’s insecure_private_key up until 4 days ago: https://github.com/theforeman/forklift/pull/635