Initialization error: RestClient::NotFound - 404 Not Found

Problem: Remote Execution of SSH Commands Fail with RestClient::NotFound -404

Expected outcome: It Should be executed successfully

Foreman and Proxy versions: 3.1.2

Foreman and Proxy plugin versions: Foreman Remote Execution Version 5.0.6

Distribution and version: CentOS 7

Other relevant data:
Hey Guys,

I am getting below error when executing remote ssh commands on target hosts.

#####################################

Host,stdout,stderr,debug,Result,Finished
xdevsl.admiral.es,"","",“Initialization error: RestClient::NotFound - 404 Not Found
Initialization error: RestClient::NotFound - 404 Not Found
Initialization error: RestClient::NotFound - 404 Not Found
Initialization error: RestClient::NotFound - 404 Not Found
Error loading data from proxy: NoMethodError - undefined method `code’ for ““404 Not Found””:String
Did you mean? encode”,error,2022-8-2 13:08:15 +0000

###############################################################

Foreman Proxy logs

##############################################################
2022-08-03T08:44:10 [D] Rack::Handler::WEBrick is invoked.
2022-08-03T08:44:10 7d8896aa [I] Started GET /dynflow/tasks/count state=running
2022-08-03T08:44:10 7d8896aa [D] verifying remote client 192.168.240.44 against trusted_hosts [“xproorchestrator05.admiral-eu.com”]
2022-08-03T08:44:10 7d8896aa [I] Finished GET /dynflow/tasks/count with 200 (4.21 ms)
2022-08-03T08:44:10 [D] close: 192.168.240.44:33670
2022-08-03T08:44:10 [D] accept: 192.168.240.44:33672
2022-08-03T08:44:10 [D] Rack::Handler::WEBrick is invoked.
2022-08-03T08:44:10 7d8896aa [I] Started POST /dynflow/tasks/launch
2022-08-03T08:44:10 7d8896aa [D] verifying remote client 192.168.240.44 against trusted_hosts [“xproorchestrator05.admiral-eu.com”]
2022-08-03T08:44:10 7d8896aa [I] Finished POST /dynflow/tasks/launch with 404 (1.26 ms)
2022-08-03T08:44:10 [D] close: 192.168.240.44:33672
2022-08-03T08:44:10 [D] accept: 192.168.240.44:33678
2022-08-03T08:44:10 [D] Rack::Handler::WEBrick is invoked.
2022-08-03T08:44:10 7d8896aa [I] Started GET /dynflow/tasks/status
2022-08-03T08:44:10 7d8896aa [D] verifying remote client 192.168.240.44 against trusted_hosts [“xproorchestrator05.admiral-eu.com”]
2022-08-03T08:44:10 7d8896aa [I] Finished GET /dynflow/tasks/status with 404 (0.74 ms)
2022-08-03T08:44:10 [D] close: 192.168.240.44:33678
2022-08-03T08:44:25 [D] accept: 192.168.240.44:34142
2022-08-03T08:44:25 [D] Rack::Handler::WEBrick is invoked.
2022-08-03T08:44:25 7d8896aa [I] Started GET /dynflow/tasks/status
2022-08-03T08:44:25 7d8896aa [D] verifying remote client 192.168.240.44 against trusted_hosts [“xproorchestrator05.admiral-eu.com”]
2022-08-03T08:44:25 7d8896aa [I] Finished GET /dynflow/tasks/status with 404 (0.67 ms)
2022-08-03T08:44:25 [D] close: 192.168.240.44:34142
2022-08-03T08:44:40 [D] accept: 192.168.240.44:34644
2022-08-03T08:44:40 [D] Rack::Handler::WEBrick is invoked.
2022-08-03T08:44:40 7d8896aa [I] Started GET /dynflow/tasks/status
2022-08-03T08:44:40 7d8896aa [D] verifying remote client 192.168.240.44 against trusted_hosts [“xproorchestrator05.admiral-eu.com”]
2022-08-03T08:44:40 7d8896aa [I] Finished GET /dynflow/tasks/status with 404 (0.76 ms)
2022-08-03T08:44:40 [D] close: 192.168.240.44:34644
2022-08-03T08:44:55 [D] accept: 192.168.240.44:35244
2022-08-03T08:44:55 [D] Rack::Handler::WEBrick is invoked.
2022-08-03T08:44:55 7d8896aa [I] Started GET /dynflow/tasks/status
2022-08-03T08:44:55 7d8896aa [D] verifying remote client 192.168.240.44 against trusted_hosts [“xproorchestrator05.admiral-eu.com”]
2022-08-03T08:44:55 7d8896aa [I] Finished GET /dynflow/tasks/status with 404 (0.74 ms)
2022-08-03T08:44:56 [D] close: 192.168.240.44:35244

################################################################################

Please do post the entire log, not just selected parts.

It is the entire log. Nothing else is there apart from this.

##########################################
2022-08-03T06:01:30 [D] Executor heartbeat
2022-08-03T06:01:48 [D] Executor heartbeat
2022-08-03T06:02:08 [D] Executor heartbeat
2022-08-03T08:40:03 [D] accept: 192.168.240.44:53686
2022-08-03T08:40:03 [D] Rack::Handler::WEBrick is invoked.
2022-08-03T08:40:03 5f0ac5c2 [I] Started GET /version
2022-08-03T08:40:03 5f0ac5c2 [I] Finished GET /version with 200 (14.37 ms)
2022-08-03T08:40:03 [D] close: 192.168.240.44:53686
2022-08-03T08:44:10 [D] accept: 192.168.240.44:33670
2022-08-03T08:44:10 [D] Rack::Handler::WEBrick is invoked.
2022-08-03T08:44:10 7d8896aa [I] Started GET /dynflow/tasks/count state=running
2022-08-03T08:44:10 7d8896aa [D] verifying remote client 192.168.240.44 against trusted_hosts [“xproorchestrator05.admiral-eu.com”]
2022-08-03T08:44:10 7d8896aa [I] Finished GET /dynflow/tasks/count with 200 (4.21 ms)
2022-08-03T08:44:10 [D] close: 192.168.240.44:33670
2022-08-03T08:44:10 [D] accept: 192.168.240.44:33672
2022-08-03T08:44:10 [D] Rack::Handler::WEBrick is invoked.
2022-08-03T08:44:10 7d8896aa [I] Started POST /dynflow/tasks/launch
2022-08-03T08:44:10 7d8896aa [D] verifying remote client 192.168.240.44 against trusted_hosts [“xproorchestrator05.admiral-eu.com”]
2022-08-03T08:44:10 7d8896aa [I] Finished POST /dynflow/tasks/launch with 404 (1.26 ms)
2022-08-03T08:44:10 [D] close: 192.168.240.44:33672
2022-08-03T08:44:10 [D] accept: 192.168.240.44:33678
2022-08-03T08:44:10 [D] Rack::Handler::WEBrick is invoked.
2022-08-03T08:44:10 7d8896aa [I] Started GET /dynflow/tasks/status
2022-08-03T08:44:10 7d8896aa [D] verifying remote client 192.168.240.44 against trusted_hosts [“xproorchestrator05.admiral-eu.com”]
2022-08-03T08:44:10 7d8896aa [I] Finished GET /dynflow/tasks/status with 404 (0.74 ms)
2022-08-03T08:44:10 [D] close: 192.168.240.44:33678
2022-08-03T08:44:25 [D] accept: 192.168.240.44:34142
2022-08-03T08:44:25 [D] Rack::Handler::WEBrick is invoked.
2022-08-03T08:44:25 7d8896aa [I] Started GET /dynflow/tasks/status
2022-08-03T08:44:25 7d8896aa [D] verifying remote client 192.168.240.44 against trusted_hosts [“xproorchestrator05.admiral-eu.com”]
2022-08-03T08:44:25 7d8896aa [I] Finished GET /dynflow/tasks/status with 404 (0.67 ms)
2022-08-03T08:44:25 [D] close: 192.168.240.44:34142
2022-08-03T08:44:40 [D] accept: 192.168.240.44:34644
2022-08-03T08:44:40 [D] Rack::Handler::WEBrick is invoked.
2022-08-03T08:44:40 7d8896aa [I] Started GET /dynflow/tasks/status
2022-08-03T08:44:40 7d8896aa [D] verifying remote client 192.168.240.44 against trusted_hosts [“xproorchestrator05.admiral-eu.com”]
2022-08-03T08:44:40 7d8896aa [I] Finished GET /dynflow/tasks/status with 404 (0.76 ms)
2022-08-03T08:44:40 [D] close: 192.168.240.44:34644
2022-08-03T08:44:55 [D] accept: 192.168.240.44:35244
2022-08-03T08:44:55 [D] Rack::Handler::WEBrick is invoked.
2022-08-03T08:44:55 7d8896aa [I] Started GET /dynflow/tasks/status
2022-08-03T08:44:55 7d8896aa [D] verifying remote client 192.168.240.44 against trusted_hosts [“xproorchestrator05.admiral-eu.com”]
2022-08-03T08:44:55 7d8896aa [I] Finished GET /dynflow/tasks/status with 404 (0.74 ms)
2022-08-03T08:44:56 [D] close: 192.168.240.44:35244
###############################################################################

The service should be logging since it started. The logs might have been rotated to another, but it should not just vanish

proxy.log (44.9 KB)
Attaching the whole file of proxy.log

If you need any other logs do please let me know

This is the relevant bit

2022-08-03T09:03:43  [W] Error details for Couldn't enable 'ssh': <RuntimeError>: Ssh public key file /var/lib/foreman-proxy/ssh/id_rsa.pub doesn't exist
/opt/theforeman/tfm/root/usr/share/gems/gems/smart_proxy_remote_execution_ssh-0.5.2/lib/smart_proxy_remote_execution_ssh.rb:20:in `validate!'
/opt/theforeman/tfm/root/usr/share/gems/gems/smart_proxy_remote_execution_ssh-0.5.2/lib/smart_proxy_remote_execution_ssh/plugin.rb:36:in `block in <class:Plugin>'
/usr/share/foreman-proxy/lib/proxy/plugin_initializer.rb:228:in `class_eval'
/usr/share/foreman-proxy/lib/proxy/plugin_initializer.rb:228:in `configure_plugin'
/usr/share/foreman-proxy/lib/proxy/plugin_initializer.rb:109:in `block in configure'
/usr/share/foreman-proxy/lib/proxy/plugin_initializer.rb:109:in `each'
/usr/share/foreman-proxy/lib/proxy/plugin_initializer.rb:109:in `configure'
/usr/share/foreman-proxy/lib/proxy/plugin_initializer.rb:187:in `each'
/usr/share/foreman-proxy/lib/proxy/plugin_initializer.rb:187:in `initialize_plugins'
/usr/share/foreman-proxy/lib/launcher.rb:173:in `launch'
/usr/share/foreman-proxy/bin/smart-proxy:6:in `<main>'

this is the root cause, or at least for now

After fixing the above issue now I am getting the below issue

#######################################
Host,stdout,stderr,debug,Result,Finished
xdevsl.admiral.es,Exit status: EXCEPTION,"","Error initializing command: RuntimeError - Unable to create directory on remote system /var/tmp/foreman-ssh-cmd-ae3e2cb0-8936-44b7-99ca-fa31e5a07b6c: exit code: 255
Permission denied (publickey,gssapi-keyex,gssapi-with-mic,password).
",error,2022-8-3 7:40:15 +0000
####################################################################

Hey Guys,

One more thing I have an old foreman setup in which this remote execution is working fine and the new one is configures exactly same as the old one. I am attaching the old foreman proxy logs as well.
old_foreman_proxy.log (13.4 KB)

There was a thread opened yesterday by you where the main topic was the exact error you’re hitting now. Maybe you didn’t really resolve that?

On a side note, claiming that two foreman instances are configured exactly the same way is a bold claim, even though it might appear so on the surface.

That’s exactly the error message from your thread Remote Execution Fails

So this should continue there and you should really fix your SSH keys…

It got resolved with changing the keys. What I really understood from yesterday till now that on new foreman setup dynflow is not working but on old its running.

############## New Foreman Output ###############################
[root@xproorchestrator05 dynflow]# ps -ef |grep -i dynflow
root 35263 33918 0 10:15 pts/0 00:00:00 grep --color=auto -i dynflow
[root@xproorchestrator05 dynflow]# systemctl status dynflowd.service
Unit dynflowd.service could not be found.
[root@xproorchestrator05 dynflow]#

#########################################################

############ Old Foreman Output #########################
[root@xproorchestrator03:/etc/smart_proxy_dynflow_core#] ps -ef |grep -i dynflow
foreman+ 2824 1 0 Jul13 ? 00:10:02 ruby /usr/bin/smart_proxy_dynflow_core -d -p /var/run/foreman-proxy/smart_proxy_dynflow_core.pid
foreman 2905 1 0 Jul13 ? 00:00:22 dynflow_executor_monitor
root 22770 20631 0 10:15 pts/2 00:00:00 grep --color=auto -i dynflow
foreman 61083 1 0 Jul27 ? 00:57:35 dynflow_executor
[root@xproorchestrator03:/etc/smart_proxy_dynflow_core#] systemctl status dynflowd.service
● dynflowd.service - Foreman jobs daemon
Loaded: loaded (/usr/lib/systemd/system/dynflowd.service; enabled; vendor preset: disabled)
Active: active (running) since Wed 2022-07-13 10:44:35 CEST; 2 weeks 6 days ago
Docs: https://theforeman.org
Process: 1721 ExecStart=/usr/sbin/dynflowd start (code=exited, status=0/SUCCESS)
Tasks: 19
CGroup: /system.slice/dynflowd.service
├─ 2905 dynflow_executor_monitor
└─61083 dynflow_executor

Warning: Journal has been rotated since unit was started. Log output is incomplete or unavailable.

#################################################################################

So if you could help me in this how I could really start dynflow on the new setup

A lot has changed between foreman 1.17 and foreman 3.1.

Simply run

# foreman-maintain health check

and it tells you if everything needed is running.

Do not attempt to activate or start deprecated services only because they were running on foreman 1.17…

Looks Like Everything is all good on new foreman

############################################################

[root@xproorchestrator05 smart_proxy_dynflow]# foreman-maintain health check
Running ForemanMaintain::Scenario::FilteredScenario

Check number of fact names in database: [OK]

Check whether all services are running: [OK]

Check whether all services are running using the ping call: [OK]

Check for paused tasks: [OK]

Check to verify no empty CA cert requests exist: [OK]

[root@xproorchestrator05 smart_proxy_dynflow]#

#####################################################################################

I also found out that dynflow core rubygem is of foreman 2 version is that ok?

[root@xproorchestrator05 smart_proxy_dynflow]# rpm -qa|grep -i dynflow
tfm-rubygem-dynflow-1.6.3-1.fm3_1.el7.noarch
tfm-rubygem-smart_proxy_dynflow-0.6.2-1.fm3_1.el7.noarch
tfm-rubygem-smart_proxy_dynflow_core-0.4.1-1.fm2_6.el7.noarch
foreman-dynflow-sidekiq-3.1.2-2.el7.noarch
dynflow-utils-1.6.3-1.el7.x86_64
[root@xproorchestrator05 smart_proxy_dynflow]#

Well, it depends. You wrote in the other thread that this is a new server. Now it looks like you have upgraded. If you have upgraded from 1.17 to 3.1.2 you do understand that you have to go through all intermediate versions as well? If you install 3.1.2 on a new server it won’t install that rpm.

I have installed it on new server. i never did upgrade. As you could see in my outputs I have 2 server running.

Well, then it’s probably still in use, but never been repackaged specifically for 3.1. It’s going to be removed with 3.2 anyway.

Ok now back to my problem of remote execution
How could we fix it ?
Please help me guys I am working on it from last 2 weeks
But I havent come to any conclusion.

What problem? You wrote you have resolved the issue, the one here as well as the one in the other thread.