Stuck Ansible remote execution jobs on Alma Linux 8.6

lkn · June 16, 2022, 9:10am

We have managed to install a new foreman 3.2.1 on a host running Alma linux 8.6 (everything latest with ansible)

We are trying to get remove execution to work.

According to my test node - the job executes (as per /var/log/secure ) we can see the user is logging in.

Our jobs is stuck in pending:

Alot of this in production.log:
2022-06-16T11:07:34 [I|app|38011423] Rendered /usr/share/gems/gems/foreman_remote_execution-6.0.0/app/views/template_invocations/show.js.erb
2022-06-16T11:07:34 [I|app|38011423] Completed 200 OK in 94ms (Views: 8.3ms | ActiveRecord: 2.1ms | Allocations: 27940)
2022-06-16T11:07:35 [I|app|c987ac28] Started GET “/notification_recipients” for 10.212.134.7 at 2022-06-16 11:07:35 +0200
2022-06-16T11:07:35 [I|app|c987ac28] Processing by NotificationRecipientsController#index as JSON
2022-06-16T11:07:35 [I|app|c987ac28] Completed 200 OK in 6ms (Views: 0.1ms | ActiveRecord: 0.9ms | Allocations: 2206)
2022-06-16T11:07:36 [I|app|5f5adad9] Started GET “/template_invocations/38?since=1655369543.3289983&line_counter=136&=1655369981478" for 10.21
2022-06-16T11:07:36 [I|app|5f5adad9] Processing by TemplateInvocationsController#show as JS
2022-06-16T11:07:36 [I|app|5f5adad9] Parameters: {“since”=>“1655369543.3289983”, “line_counter”=>“136”, "”=>“1655369981478”, “id”=>“38”}
2022-06-16T11:07:36 [I|app|5f5adad9] Rendering /usr/share/gems/gems/foreman_remote_execution-6.0.0/app/views/template_invocations/show.js.erb
2022-06-16T11:07:36 [I|app|5f5adad9] Rendered collection of /usr/share/gems/gems/foreman_remote_execution-6.0.0/app/views/template_invocation
2022-06-16T11:07:36 [I|app|5f5adad9] Rendered /usr/share/gems/gems/foreman_remote_execution-6.0.0/app/views/template_invocations/_refresh.js.
2022-06-16T11:07:36 [I|app|5f5adad9] Rendered /usr/share/gems/gems/foreman_remote_execution-6.0.0/app/views/template_invocations/show.js.erb
2022-06-16T11:07:36 [I|app|5f5adad9] Completed 200 OK in 93ms (Views: 8.7ms | ActiveRecord: 2.6ms | Allocations: 27940)
2022-06-16T11:07:38 [E|bac|34048838] A sub task failed (RuntimeError)
34048838 | /usr/share/gems/gems/dynflow-1.6.4/lib/dynflow/action/with_sub_plans.rb:231:in check_for_errors!' 34048838 | /usr/share/gems/gems/dynflow-1.6.4/lib/dynflow/action/with_sub_plans.rb:137:in try_to_finish’
34048838 | /usr/share/gems/gems/dynflow-1.6.4/lib/dynflow/action/with_polling_sub_plans.rb:19:in poll' 34048838 | /usr/share/gems/gems/dynflow-1.6.4/lib/dynflow/action/with_polling_sub_plans.rb:11:in run’
34048838 | /usr/share/gems/gems/foreman_remote_execution-6.0.0/app/lib/actions/remote_execution/run_hosts_job.rb:140:in run' 34048838 | /usr/share/gems/gems/dynflow-1.6.4/lib/dynflow/action.rb:582:in block (3 levels) in execute_run’
34048838 | /usr/share/gems/gems/dynflow-1.6.4/lib/dynflow/middleware/stack.rb:27:in pass' 34048838 | /usr/share/gems/gems/dynflow-1.6.4/lib/dynflow/middleware.rb:19:in pass’
34048838 | /usr/share/gems/gems/foreman-tasks-6.0.1/app/lib/actions/middleware/watch_delegated_proxy_sub_tasks.rb:17:in run' 34048838 | /usr/share/gems/gems/dynflow-1.6.4/lib/dynflow/middleware/stack.rb:23:in call’
34048838 | /usr/share/gems/gems/dynflow-1.6.4/lib/dynflow/middleware/stack.rb:27:in pass' 34048838 | /usr/share/gems/gems/dynflow-1.6.4/lib/dynflow/middleware.rb:19:in pass’
34048838 | /usr/share/gems/gems/dynflow-1.6.4/lib/dynflow/middleware.rb:32:in run' 34048838 | /usr/share/gems/gems/dynflow-1.6.4/lib/dynflow/middleware/stack.rb:23:in call’
34048838 | /usr/share/gems/gems/dynflow-1.6.4/lib/dynflow/middleware/stack.rb:27:in pass' 34048838 | /usr/share/gems/gems/dynflow-1.6.4/lib/dynflow/middleware.rb:19:in pass’
34048838 | /usr/share/gems/gems/dynflow-1.6.4/lib/dynflow/middleware.rb:32:in run' 34048838 | /usr/share/gems/gems/dynflow-1.6.4/lib/dynflow/middleware/stack.rb:23:in call’
34048838 | /usr/share/gems/gems/dynflow-1.6.4/lib/dynflow/middleware/stack.rb:27:in pass' 34048838 | /usr/share/gems/gems/dynflow-1.6.4/lib/dynflow/middleware.rb:19:in pass’
34048838 | /usr/share/gems/gems/foreman-tasks-6.0.1/app/lib/actions/middleware/rails_executor_wrap.rb:14:in block in run' 34048838 | /usr/share/gems/gems/activesupport-6.0.3.7/lib/active_support/execution_wrapper.rb:88:in wrap’
34048838 | /usr/share/gems/gems/foreman-tasks-6.0.1/app/lib/actions/middleware/rails_executor_wrap.rb:13:in run' 34048838 | /usr/share/gems/gems/dynflow-1.6.4/lib/dynflow/middleware/stack.rb:23:in call’
34048838 | /usr/share/gems/gems/dynflow-1.6.4/lib/dynflow/middleware/stack.rb:27:in pass' 34048838 | /usr/share/gems/gems/dynflow-1.6.4/lib/dynflow/middleware.rb:19:in pass’

aruzicka · June 16, 2022, 9:47am

Hi,
what do the logs in /var/log/foreman-proxy/proxy.log say?

lkn · June 16, 2022, 9:54am

Hi

Alot of this:
2022-06-16T11:53:28 cf941372 [I] Started GET /dynflow/tasks/47af1a52-9fd2-4b27-aa87-c8493ca4f541/status
2022-06-16T11:53:28 cf941372 [I] Finished GET /dynflow/tasks/47af1a52-9fd2-4b27-aa87-c8493ca4f541/status with 404 (0.74 ms)
2022-06-16T11:53:28 cf941372 [I] Started GET /dynflow/tasks/47af1a52-9fd2-4b27-aa87-c8493ca4f541/status
2022-06-16T11:53:28 cf941372 [I] Finished GET /dynflow/tasks/47af1a52-9fd2-4b27-aa87-c8493ca4f541/status with 404 (0.71 ms)
2022-06-16T11:53:29 8ac4a518 [I] Started GET /dynflow/tasks/48567047-63cc-499a-ba5b-ffa96e037f42/status
2022-06-16T11:53:29 8ac4a518 [I] Finished GET /dynflow/tasks/48567047-63cc-499a-ba5b-ffa96e037f42/status with 200 (4.98 ms)
2022-06-16T11:53:30 6a4d6ce1 [I] Started GET /dynflow/tasks/47af1a52-9fd2-4b27-aa87-c8493ca4f541/status
2022-06-16T11:53:30 6a4d6ce1 [I] Finished GET /dynflow/tasks/47af1a52-9fd2-4b27-aa87-c8493ca4f541/status with 404 (0.73 ms)
2022-06-16T11:53:30 6a4d6ce1 [I] Started GET /dynflow/tasks/47af1a52-9fd2-4b27-aa87-c8493ca4f541/status
2022-06-16T11:53:30 6a4d6ce1 [I] Finished GET /dynflow/tasks/47af1a52-9fd2-4b27-aa87-c8493ca4f541/status with 404 (0.76 ms)
2022-06-16T11:53:31 1f410a10 [I] Started GET /dynflow/tasks/48567047-63cc-499a-ba5b-ffa96e037f42/status
2022-06-16T11:53:31 1f410a10 [I] Finished GET /dynflow/tasks/48567047-63cc-499a-ba5b-ffa96e037f42/status with 200 (4.22 ms)
2022-06-16T11:53:32 e22eda61 [I] Started GET /dynflow/tasks/47af1a52-9fd2-4b27-aa87-c8493ca4f541/status
2022-06-16T11:53:32 e22eda61 [I] Finished GET /dynflow/tasks/47af1a52-9fd2-4b27-aa87-c8493ca4f541/status with 404 (0.78 ms)
2022-06-16T11:53:32 e22eda61 [I] Started GET /dynflow/tasks/47af1a52-9fd2-4b27-aa87-c8493ca4f541/status
2022-06-16T11:53:32 e22eda61 [I] Finished GET /dynflow/tasks/47af1a52-9fd2-4b27-aa87-c8493ca4f541/status with 404 (0.84 ms)
2022-06-16T11:53:33 f215e261 [I] Started GET /dynflow/tasks/48567047-63cc-499a-ba5b-ffa96e037f42/status
2022-06-16T11:53:33 f215e261 [I] Finished GET /dynflow/tasks/48567047-63cc-499a-ba5b-ffa96e037f42/status with 200 (3.83 ms)
2022-06-16T11:53:34 d630af3f [I] Started GET /dynflow/tasks/47af1a52-9fd2-4b27-aa87-c8493ca4f541/status
2022-06-16T11:53:34 d630af3f [I] Finished GET /dynflow/tasks/47af1a52-9fd2-4b27-aa87-c8493ca4f541/status with 404 (0.93 ms)
2022-06-16T11:53:34 d630af3f [I] Started GET /dynflow/tasks/47af1a52-9fd2-4b27-aa87-c8493ca4f541/status
2022-06-16T11:53:34 d630af3f [I] Finished GET /dynflow/tasks/47af1a52-9fd2-4b27-aa87-c8493ca4f541/status with 404 (0.89 ms)
2022-06-16T11:53:35 792bd24f [I] Started GET /dynflow/tasks/48567047-63cc-499a-ba5b-ffa96e037f42/status
2022-06-16T11:53:35 792bd24f [I] Finished GET /dynflow/tasks/48567047-63cc-499a-ba5b-ffa96e037f42/status with 200 (3.78 ms)
2022-06-16T11:53:36 41d266c6 [I] Started GET /dynflow/tasks/47af1a52-9fd2-4b27-aa87-c8493ca4f541/status
2022-06-16T11:53:36 41d266c6 [I] Finished GET /dynflow/tasks/47af1a52-9fd2-4b27-aa87-c8493ca4f541/status with 404 (0.82 ms)
2022-06-16T11:53:36 41d266c6 [I] Started GET /dynflow/tasks/47af1a52-9fd2-4b27-aa87-c8493ca4f541/status
2022-06-16T11:53:36 41d266c6 [I] Finished GET /dynflow/tasks/47af1a52-9fd2-4b27-aa87-c8493ca4f541/status with 404 (0.76 ms)
2022-06-16T11:53:37 e95dfdaf [I] Started GET /dynflow/tasks/48567047-63cc-499a-ba5b-ffa96e037f42/status
2022-06-16T11:53:37 e95dfdaf [I] Finished GET /dynflow/tasks/48567047-63cc-499a-ba5b-ffa96e037f42/status with 200 (6.24 ms)
2022-06-16T11:53:38 d98c9349 [I] Started GET /dynflow/tasks/47af1a52-9fd2-4b27-aa87-c8493ca4f541/status
2022-06-16T11:53:38 d98c9349 [I] Finished GET /dynflow/tasks/47af1a52-9fd2-4b27-aa87-c8493ca4f541/status with 404 (0.8 ms)
2022-06-16T11:53:38 d98c9349 [I] Started GET /dynflow/tasks/47af1a52-9fd2-4b27-aa87-c8493ca4f541/status
2022-06-16T11:53:38 d98c9349 [I] Finished GET /dynflow/tasks/47af1a52-9fd2-4b27-aa87-c8493ca4f541/status with 404 (0.81 ms)
2022-06-16T11:53:39 ceb384d2 [I] Started GET /dynflow/tasks/48567047-63cc-499a-ba5b-ffa96e037f42/status
2022-06-16T11:53:39 ceb384d2 [I] Finished GET /dynflow/tasks/48567047-63cc-499a-ba5b-ffa96e037f42/status with 200 (3.85 ms)
2022-06-16T11:53:40 8cd7d366 [I] Started GET /dynflow/tasks/47af1a52-9fd2-4b27-aa87-c8493ca4f541/status
2022-06-16T11:53:40 8cd7d366 [I] Finished GET /dynflow/tasks/47af1a52-9fd2-4b27-aa87-c8493ca4f541/status with 404 (0.88 ms)
2022-06-16T11:53:40 8cd7d366 [I] Started GET /dynflow/tasks/47af1a52-9fd2-4b27-aa87-c8493ca4f541/status
2022-06-16T11:53:40 8cd7d366 [I] Finished GET /dynflow/tasks/47af1a52-9fd2-4b27-aa87-c8493ca4f541/status with 404 (0.84 ms)
2022-06-16T11:53:41 fe6285b0 [I] Started GET /dynflow/tasks/48567047-63cc-499a-ba5b-ffa96e037f42/status
2022-06-16T11:53:41 fe6285b0 [I] Finished GET /dynflow/tasks/48567047-63cc-499a-ba5b-ffa96e037f42/status with 200 (4.08 ms)

i can attach the entire file

lkn · June 16, 2022, 10:00am

proxy.log (2.8 MB)
Here is the entire log not really much besides a single ssl error.

lkn · June 16, 2022, 10:01am

Just stuck here.,

aruzicka · June 16, 2022, 10:28am

Looks like some misconfiguration around ssl certs. This is the important bit from the logs

2022-06-16T11:53:53 27587354 [E] <OpenSSL::SSL::SSLError> SSL_connect returned=1 errno=0 state=error: certificate verify failed (unable to get local issuer certificate)
	/usr/share/ruby/net/protocol.rb:44:in `connect_nonblock'
	/usr/share/ruby/net/protocol.rb:44:in `ssl_socket_connect'
	/usr/share/ruby/net/http.rb:1009:in `connect'
	/usr/share/ruby/net/http.rb:943:in `do_start'
	/usr/share/ruby/net/http.rb:932:in `start'
	/usr/share/ruby/net/http.rb:1483:in `request'
	/usr/share/foreman-proxy/lib/proxy/request.rb:48:in `send_request'
	/usr/share/gems/gems/smart_proxy_dynflow-0.7.0/lib/smart_proxy_dynflow/callback.rb:13:in `callback'
	/usr/share/gems/gems/smart_proxy_dynflow-0.7.0/lib/smart_proxy_dynflow/callback.rb:7:in `send_to_foreman_tasks'

The job runs, eventually finishes and then the smart proxy tries to call back to foreman, but that callback fails.

lkn · June 16, 2022, 10:34am

Hi im a little in doubt which certificates it is ansible needs to be able to a proper call back?

we have utilizing a 3rd party ssl for the web interface (all good and working) or should it require the default on for puppet ca?

callback_enabled = theforeman.foreman.foreman
local_tmp = /tmp
host_key_checking = False
stdout_callback = yaml
roles_path = /etc/ansible/roles:/usr/share/ansible/roles
collections_paths = /etc/ansible/collections:/usr/share/ansible/collections

[callback_foreman]
report_type = foreman
proxy_url = https://fqdn:8443
url = https://fqdn
ssl_cert = /etc/puppetlabs/puppet/ssl/certs/fqdn.io.pem
ssl_key = /etc/puppetlabs/puppet/ssl/private_keys/fqdn.io.pem
verify_certs = false

[ssh_connection]
ssh_args = -o ProxyCommand=none -C -o ControlMaster=auto -o ControlPersist=60s

aruzicka · June 16, 2022, 10:45am

It is not ansible, it is smart proxy. /etc/foreman-proxy/settings.yaml is the place to look at

This could be it, it feels like the certs have not been propagated to all the places where they need to be used

lkn · June 16, 2022, 10:50am

Is there any log settings or other that can help us create a conclusion on whats causing this issue?

aruzicka · June 16, 2022, 11:01am

No, but it should be fairly straightforward to replicate by just doing curl against Foreman using the certs configured in /etc/foreman-proxy/settings.yaml

lkn · June 16, 2022, 11:09am

your thinking just against the default interface?

lkn · June 16, 2022, 11:12am

I just dont get what makes the job stuck - i assume its because the proxy cannot return the state to foreman and it will let the job be stuck until?

aruzicka · June 16, 2022, 11:19am

Default interface of what?

That’s correct. Most likely because the smart proxy does not trust the CA that signed certs that Foreman’s webui uses.

lkn · June 16, 2022, 11:57am

Hi,

So we reverted all certs back to defaults and everything works including the the proxy and the remote jobs

A bit sad as it concludes the ssl configuration can be quite complex and alot of room for errors ( Feature request: more simple ssl configuration)

So basicly if we wish to use a 3rd party cert we have to go back to the drawing bord or move on as it is with the selfsigned.

aruzicka · June 16, 2022, 12:25pm

Sadly yes. It should be possible, although I never even attempted it myself so I can’t really walk you through it.

The important thing is that you can configure two sets of certs for smart proxy, one is used for its rest interface, the other (foreman_ssl*) is used when making outgoing calls to foreman.