Finished GET /dynflow/tasks/status with 404

Problem:
Running a remote execution job, the jobs that run on one of the smart proxy return messages like this

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 FoundError loading data from proxy: NoMethodError - undefined method `code' for "404 Not Found":String
Did you mean?  encode

Looking at the Smart Proxy logs, I see messages like this
Finished GET /dynflow/tasks/status with 404

Expected outcome:
Job should run normally and output should be shown in console

Foreman and Proxy versions:
Foreman 3.1.0 and after upgrading the affected smart proxy is 3.1.1, but this looked like it was happening even on 3.1.0

Distribution and version:
CentOS 7.9

Other relevant data:
There was a similar thread here Remote execution don't work - #6 by flynet70 but that looked like it was affecting Debian, and @aruzicka asked to start a new thread

Pasting logs from the other thread

2022-01-27T09:28:48 [D] Rack::Handler::WEBrick is invoked.
2022-01-27T09:28:48 49c831df [I] Started GET /dynflow/tasks/count state=running
2022-01-27T09:28:48 49c831df [D] verifying remote client foreman against trusted_hosts [“foreman”, “foreman-proxy-mdw”]
2022-01-27T09:28:48 49c831df [I] Finished GET /dynflow/tasks/count with 200 (1.03 ms)
2022-01-27T09:28:48 [D] close: foreman:55984
2022-01-27T09:28:49 [D] accept: foreman:56002
2022-01-27T09:28:49 [D] accept: foreman:56004
2022-01-27T09:28:49 [D] Rack::Handler::WEBrick is invoked.
2022-01-27T09:28:49 49c831df [I] Started GET /dynflow/tasks/status
2022-01-27T09:28:49 49c831df [D] verifying remote client foreman against trusted_hosts [“foreman”, “foreman-mdw”]
2022-01-27T09:28:49 49c831df [I] Finished GET /dynflow/tasks/status with 404 (0.52 ms)
2022-01-27T09:28:49 [D] Rack::Handler::WEBrick is invoked.
2022-01-27T09:28:49 49c831df [I] Started GET /dynflow/tasks/status
2022-01-27T09:28:49 49c831df [D] verifying remote client foreman against trusted_hosts [“foreman”, “foreman-mdw”]
2022-01-27T09:28:49 49c831df [I] Finished GET /dynflow/tasks/status with 404 (0.48 ms)
2022-01-27T09:28:49 [D] close: foreman:56002
2022-01-27T09:28:49 [D] close: foreman:56004

If the logs are complete then there is no POST to /dynflow/tasks/launch, which would mean the job is never triggered on the proxy in question. Do you have several proxies behind a load balancer by any chance?

I only have 2 smart proxies, the “main” one where foreman runs itself, and a “remote” smart proxy in another location. It seems like only jobs that use the remote smart proxy are affected by this. The regular foreman smart proxy works fine.

Also it seems like this only happens when I run a job with multiple hosts, and Foreman is trying to do some load balancing with both of the smart proxies. Only the hosts that use the remote proxy return the 404 error.

If I run a job on a single host that uses the remote proxy, then it works fine. Almost like the parent task is having trouble being passed down when there are multiple hosts using the remote smart proxy

Could you bump log level to debug on both proxies and run a job with many hosts so they go through both proxies and then upload logs from both proxies so we cant cross reference them and establish a timeline?

Attached is logs from remote proxy (with 404 status), main proxy (no errors), and production.log (with dynflow errors)

remote-smart-proxy.log (8.1 KB)
main-smart-proxy.log (30.6 KB)
production.log (244.2 KB)

Production.log has this

2022-02-08T05:02:42 [W|bac|4ac20229] Could not trigger task on the smart proxy: undefined method `[]' for nil:NilClass

Which leads us here[1]. The failure seems to happen before it tries to reach out to the remote proxy, but there aren’t all that many places where it could go wrong and I can’t really see where a rogue nil could sneak in within the normal operating conditions. We’d definitely need better logging in this area, would you be willing to try a patch[2]? I’m failing to reproduce it locally

[1] - https://github.com/theforeman/foreman-tasks/blob/master/app/lib/actions/trigger_proxy_batch.rb#L43
[2] - https://github.com/theforeman/foreman-tasks/pull/671

Sure, could you walk me though how to apply the patch? I have not done it before. Is it just a matter of editing one line in the file on the server?

Correct, although I usually apply whole patches instead of changing things by hand.

cd /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.1

# Commit the source from rpm into a git repository so we can go back if things go south
git init
git add .
git commit -m rpm
git tag rpm

# Normally it would be just a matter of
# curl -L https://github.com/theforeman/foreman-tasks/pull/671.patch | git am
# but the PR doesn't apply cleanly against 5.2.1

# Here's a 5.2.1 compatible version of the same fix
curl -L https://github.com/theforeman/foreman-tasks/compare/5.2.x...adamruzicka:3.1/error-logging.patch | git am

# Restart all services which load that code
systemctl restart foreman 'dynflow-sidekiq@*'

# If things go awry we can just
# git reset --hard rpm
# rm -rf .git

Thanks, my foreman-tasks is actually 5.2.0, but I was able to apply the patch, and this is the output I get when I re-run that same job.

2022-02-08T07:46:11 [W|bac|113dbd4d] Could not trigger task on the smart proxy
2022-02-08T07:46:11 [W|bac|113dbd4d] undefined method `[]' for nil:NilClass (NoMethodError)
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/models/foreman_tasks/remote_task.rb:42:in `update_from_batch_trigger'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/models/foreman_tasks/remote_task.rb:36:in `block (2 levels) in batch_trigger'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/models/foreman_tasks/remote_task.rb:36:in `each'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/models/foreman_tasks/remote_task.rb:36:in `block in batch_trigger'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/models/foreman_tasks/remote_task.rb:30:in `map'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/models/foreman_tasks/remote_task.rb:30:in `batch_trigger'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/trigger_proxy_batch.rb:39:in `block in trigger_remote_tasks_batch'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/trigger_proxy_batch.rb:38:in `each'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/trigger_proxy_batch.rb:38:in `trigger_remote_tasks_batch'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/trigger_proxy_batch.rb:23:in `run'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/action.rb:582:in `block (3 levels) in execute_run'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/middleware/stack.rb:27:in `pass'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/middleware.rb:19:in `pass'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/rails_executor_wrap.rb:14:in `block in run'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.7/lib/active_support/execution_wrapper.rb:88:in `wrap'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/rails_executor_wrap.rb:13:in `run'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/middleware/stack.rb:23:in `call'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/middleware/stack.rb:27:in `pass'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/middleware.rb:19:in `pass'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/action/progress.rb:31:in `with_progress_calculation'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/action/progress.rb:17:in `run'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/middleware/stack.rb:23:in `call'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/middleware/stack.rb:27:in `pass'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/middleware.rb:19:in `pass'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/load_setting_values.rb:20:in `run'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/middleware/stack.rb:23:in `call'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/middleware/stack.rb:27:in `pass'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/middleware.rb:19:in `pass'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/keep_current_request_id.rb:15:in `block in run'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/keep_current_request_id.rb:52:in `restore_current_request_id'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/keep_current_request_id.rb:15:in `run'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/middleware/stack.rb:23:in `call'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/middleware/stack.rb:27:in `pass'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/middleware.rb:19:in `pass'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/keep_current_timezone.rb:15:in `block in run'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/keep_current_timezone.rb:44:in `restore_curent_timezone'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/keep_current_timezone.rb:15:in `run'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/middleware/stack.rb:23:in `call'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/middleware/stack.rb:27:in `pass'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/middleware.rb:19:in `pass'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/keep_current_taxonomies.rb:15:in `block in run'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/keep_current_taxonomies.rb:45:in `restore_current_taxonomies'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/keep_current_taxonomies.rb:15:in `run'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/middleware/stack.rb:23:in `call'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/middleware/stack.rb:27:in `pass'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/middleware.rb:19:in `pass'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/middleware.rb:32:in `run'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/middleware/stack.rb:23:in `call'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/middleware/stack.rb:27:in `pass'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/middleware.rb:19:in `pass'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/keep_current_user.rb:15:in `block in run'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/keep_current_user.rb:54:in `restore_curent_user'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/keep_current_user.rb:15:in `run'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/middleware/stack.rb:23:in `call'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/middleware/world.rb:31:in `execute'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/action.rb:581:in `block (2 levels) in execute_run'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/action.rb:580:in `catch'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/action.rb:580:in `block in execute_run'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/action.rb:483:in `block in with_error_handling'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/action.rb:483:in `catch'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/action.rb:483:in `with_error_handling'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/action.rb:575:in `execute_run'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/action.rb:296:in `execute'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:18:in `block (2 levels) in execute'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/execution_plan/steps/abstract.rb:167:in `with_meta_calculation'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:17:in `block in execute'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:32:in `open_action'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:16:in `execute'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/director.rb:94:in `execute'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/executors/sidekiq/worker_jobs.rb:11:in `block (2 levels) in perform'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/executors.rb:18:in `run_user_code'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/executors/sidekiq/worker_jobs.rb:9:in `block in perform'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/executors/sidekiq/worker_jobs.rb:25:in `with_telemetry'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/executors/sidekiq/worker_jobs.rb:8:in `perform'
 113dbd4d | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.2/lib/dynflow/executors/sidekiq/serialization.rb:27:in `perform'
 113dbd4d | [ sidekiq ]
 113dbd4d | [ concurrent-ruby ]

Hmm, now this is unexpected.

It fails when processing a response from the remote proxy, but the remote proxy shows no sign of receiving the request and responding to it.

So either it hits some other host/service, but it still replies somewhat successfully, or it hits the right proxy but for some reason the proxy doesn’t log it.

Refreshing features on the remote proxy works as expected? What versions of smart proxy plugins do you have on both the proxies?

Yes, refreshing features works on both smart proxies. I tried to bump up the version of the remote proxy to 3.1.1 but same issue was still occurring on older 3.1.0 version

And yea, remote proxy will work if its just a single host. Only has an issue when there is more than one host.

remote proxy

Ansible

Version
3.3.0

Container_Gateway

Version
1.0.6

Discovery

Version
1.0.5

Dynflow

Version
0.6.1

HTTPBoot

Version
3.1.1

Content

Version
3.2.0
Supported Content Types

  • ansible_collection
  • deb
  • docker
  • file
  • python
  • yum

Registration

Version
3.1.1

SSH

Version
0.5.1

TFTP

Version
3.1.1
TFTP server
false

Templates

Version
3.1.1

main-proxy

Ansible

Version
3.3.0

BMC

Version
3.1.0

DNS

Version
3.1.0

Discovery

Version
1.0.5

Dynflow

Version
0.6.1

HTTPBoot

Version
3.1.0

Openscap

Version
0.9.1

Content

Version
3.2.0
Supported Content Types

  • ansible_collection
  • deb
  • docker
  • file
  • python
  • yum

Registration

Version
3.1.0

SSH

Version
0.5.1

TFTP

Version
3.1.0
TFTP server
false

Templates

Version
3.1.0

@aruzicka I’m also affected by this issue. I’m using Foreman 3.1.1 with updated smart proxies on CentOS7. I’m experiencing roughly the same issue as the OP. I’m using the internal capsule of Foreman as well as a external smart proxy. When I run a bulk task with 5-10 hosts included in the remote execution job, there’s a few that will execute successfully but the remaining will result in the below error

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 FoundError loading data from proxy: NoMethodError - undefined method `code' for "404 Not Found":String
Did you mean?  encode

foreman-proxy

2022-02-08T20:47:00 ac60d09f [I] Started GET /dynflow/tasks/status 
2022-02-08T20:47:00 ac60d09f [I] Finished GET /dynflow/tasks/status with 404 (0.63 ms)
2022-02-08T20:47:15 ac60d09f [I] Started GET /dynflow/tasks/status 
2022-02-08T20:47:15 ac60d09f [I] Finished GET /dynflow/tasks/status with 404 (0.67 ms)
2022-02-08T20:47:15 ac60d09f [I] Started GET /dynflow/tasks/status 
2022-02-08T20:47:15 ac60d09f [I] Finished GET /dynflow/tasks/status with 404 (0.53 ms)
2022-02-08T20:47:30 ac60d09f [I] Started GET /dynflow/tasks/status 
2022-02-08T20:47:30 ac60d09f [I] Finished GET /dynflow/tasks/status with 404 (0.47 ms)
2022-02-08T20:47:30 ac60d09f [I] Started GET /dynflow/tasks/status 
2022-02-08T20:47:30 ac60d09f [I] Finished GET /dynflow/tasks/status with 404 (0.47 ms)
2022-02-08T20:47:45 ac60d09f [I] Started GET /dynflow/tasks/status 
2022-02-08T20:47:45 ac60d09f [I] Finished GET /dynflow/tasks/status with 404 (0.49 ms)
2022-02-08T20:47:45 ac60d09f [I] Started GET /dynflow/tasks/status 
2022-02-08T20:47:45 ac60d09f [I] Finished GET /dynflow/tasks/status with 404 (0.45 ms)

foreman production

2022-02-08T20:47:45 [E|bac|ac60d09f] 404 Not Found (RestClient::NotFound)
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-2.0.2/lib/restclient/abstract_response.rb:223:in `exception_with_response'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-2.0.2/lib/restclient/abstract_response.rb:103:in `return!'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-2.0.2/lib/restclient/request.rb:809:in `process_result'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-2.0.2/lib/restclient/request.rb:725:in `block in transmit'
 ac60d09f | /opt/rh/rh-ruby27/root/usr/share/ruby/net/http.rb:933:in `start'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-2.0.2/lib/restclient/request.rb:715:in `transmit'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-2.0.2/lib/restclient/request.rb:145:in `execute'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-2.0.2/lib/restclient/request.rb:52:in `execute'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-2.0.2/lib/restclient/resource.rb:51:in `get'
 ac60d09f | /usr/share/foreman/lib/proxy_api/resource.rb:72:in `block (2 levels) in get'
 ac60d09f | /usr/share/foreman/app/services/foreman/telemetry_helper.rb:28:in `telemetry_duration_histogram'
 ac60d09f | /usr/share/foreman/lib/proxy_api/resource.rb:69:in `block in get'
 ac60d09f | /usr/share/foreman/lib/proxy_api/resource.rb:112:in `with_logger'
 ac60d09f | /usr/share/foreman/lib/proxy_api/resource.rb:68:in `get'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/proxy_api/foreman_dynflow/dynflow_proxy.rb:31:in `status_of_task'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/proxy_action.rb:87:in `check_task_status'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/proxy_action.rb:137:in `on_proxy_action_stopped'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/proxy_action.rb:56:in `block in run'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/proxy_action.rb:225:in `with_connection_error_handling'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/proxy_action.rb:41:in `run'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/action.rb:582:in `block (3 levels) in execute_run'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware/stack.rb:27:in `pass'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware.rb:19:in `pass'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware.rb:32:in `run'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware/stack.rb:23:in `call'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware/stack.rb:27:in `pass'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware.rb:19:in `pass'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/rails_executor_wrap.rb:14:in `block in run'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.7/lib/active_support/execution_wrapper.rb:88:in `wrap'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/rails_executor_wrap.rb:13:in `run'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware/stack.rb:23:in `call'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware/stack.rb:27:in `pass'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware.rb:19:in `pass'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/action/progress.rb:31:in `with_progress_calculation'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/action/progress.rb:17:in `run'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware/stack.rb:23:in `call'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware/stack.rb:27:in `pass'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware.rb:19:in `pass'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/load_setting_values.rb:20:in `run'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware/stack.rb:23:in `call'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware/stack.rb:27:in `pass'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware.rb:19:in `pass'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/keep_current_request_id.rb:15:in `block in run'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/keep_current_request_id.rb:52:in `restore_current_request_id'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/keep_current_request_id.rb:15:in `run'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware/stack.rb:23:in `call'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware/stack.rb:27:in `pass'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware.rb:19:in `pass'
c60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/keep_current_timezone.rb:15:in `block in run'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/keep_current_timezone.rb:44:in `restore_curent_timezone'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/keep_current_timezone.rb:15:in `run'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware/stack.rb:23:in `call'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware/stack.rb:27:in `pass'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware.rb:19:in `pass'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/keep_current_taxonomies.rb:15:in `block in run'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/keep_current_taxonomies.rb:45:in `restore_current_taxonomies'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/keep_current_taxonomies.rb:15:in `run'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware/stack.rb:23:in `call'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware/stack.rb:27:in `pass'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware.rb:19:in `pass'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware.rb:32:in `run'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware/stack.rb:23:in `call'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware/stack.rb:27:in `pass'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware.rb:19:in `pass'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/keep_current_user.rb:15:in `block in run'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/keep_current_user.rb:54:in `restore_curent_user'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/keep_current_user.rb:15:in `run'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware/stack.rb:23:in `call'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware/world.rb:31:in `execute'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/action.rb:581:in `block (2 levels) in execute_run'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/action.rb:580:in `catch'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/action.rb:580:in `block in execute_run'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/action.rb:483:in `block in with_error_handling'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/action.rb:483:in `catch'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/action.rb:483:in `with_error_handling'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/action.rb:575:in `execute_run'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/action.rb:296:in `execute'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:18:in `block (2 levels) in execute'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/execution_plan/steps/abstract.rb:167:in `with_meta_calculation'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:17:in `block in execute'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:32:in `open_action'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:16:in `execute'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/director.rb:94:in `execute'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/executors/sidekiq/worker_jobs.rb:11:in `block (2 levels) in perform'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/executors.rb:18:in `run_user_code'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/executors/sidekiq/worker_jobs.rb:9:in `block in perform'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/executors/sidekiq/worker_jobs.rb:25:in `with_telemetry'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/executors/sidekiq/worker_jobs.rb:8:in `perform'
 ac60d09f | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/executors/sidekiq/serialization.rb:27:in `perform'
 ac60d09f | [ sidekiq ]
 ac60d09f | [ concurrent-ruby ]

@aruzicka is there any assistance you can provide or is there any additional information you need in helping resolve this?

Sorry about the delay, I haven’t forgotten about this, I was just out sick for a couple of days. Now that I’m back, I managed to put together a reproducer and once I had it, fixing it was easy.

It is being tracked as [1], with patches being opened for nightly[2] and 3.1-compatible[3].

[1] - Bug #34447: Proxy batch triggering fails if there are multiple proxies in a single batch - foreman-tasks - Foreman
[2] - https://github.com/theforeman/foreman-tasks/pull/672
[3] - https://github.com/theforeman/foreman-tasks/pull/673

2 Likes

@aruzicka I updated Foreman to 3.1.2 (along with all the other plugins) and can confirm that this issue is now fixed.

Thanks for the help!

@aruzicka

I still seem to be plagued by this issue. I’m running Foreman 3.2.0, same version on the smart proxies … this issue is sort of preventing me from moving forward with the integration of Foreman in the environment I’m working in … I decided to try to avoid this issue by using a single smart proxy, but I still seem to have the same issues as before. I can get away with running a batch job of 15 or so hosts, but if trying to run a job on every server in the environment (currently only 170 or so hosts), about 60% of the hosts are failing like this:

31 :Error loading data from proxy: RestClient::NotFound - 404 Not Found
32: Error loading data from proxy: RestClient::NotFound - 404 Not Found
33: Error loading data from proxy: RestClient::NotFound - 404 Not Found
34: Error loading data from proxy: RestClient::NotFound - 404 Not Found
35: Error loading data from proxy: RestClient::NotFound - 404 Not Found
36: Error initializing command: RuntimeError - Unable to create directory on remote system /var/tmp/foreman-ssh-cmd-f8e1b393-d3c2-4d60-9775-b7c48ea2cfb8: exit code: 255
37:
38:
Exit status: EXCEPTION

The ssh error at the bottom is bizarre because if I run a ssh job on the individual hosts that are producing that error outside of a large batch job, I’m able to successfully perform remote execution using the same exact smart proxy. Has this change made it into the 3.2.0 release yet, or am I looking at a different issue?

Thanks

The fix landed in foreman-tasks-6.0.1, which is in 3.2 repos so if you’re on that version, I’d be inclined to say what you’re hitting is a different issue. Could you start a new thread and attach logs (/var/log/foreman/production.log from foreman, /var/log/foreman-proxy/proxy.log from the proxy, /var/log/secure from one of the target hosts)?

So the updates with the foreman-tasks fixes wasn’t included in the initial release of 3.2.0 which confused me a bit, it wasn’t included into the repository until April 7th or something like that. I performed a update in my environment for foreman and it’s proxies and the issue now seems to be resolved and is reporting more clear errors if something were to go wrong with remote executions. Appreciate the help, if in fact I do have more issues relating to this I’ll let you know.

Thanks