Problem:
When I try to execute “Run ansible roles” the job starts, but never finishes.
As in other similar problems, no login attempt is done on the remote system, The foreman proxy log gives the following error:
2021-12-14T19:39:18 [E] error while dispatching request to runner bd61b241-d120-459f-9d21-85b56518018b:TypeError no implicit conversion of nil into String:
/usr/share/gems/gems/smart_proxy_ansible-3.2.1/lib/smart_proxy_ansible/runner/ansible_runner.rb:34:in `basename'
/usr/share/gems/gems/smart_proxy_ansible-3.2.1/lib/smart_proxy_ansible/runner/ansible_runner.rb:34:in `refresh'
/usr/share/gems/gems/smart_proxy_dynflow-0.5.2/lib/smart_proxy_dynflow/runner/base.rb:21:in `run_refresh'
/usr/share/gems/gems/smart_proxy_dynflow-0.5.2/lib/smart_proxy_dynflow/runner/dispatcher.rb:40:in `refresh_runner'
/usr/share/gems/gems/dynflow-1.5.0/lib/dynflow/actor.rb:13:in `on_message'
Expected outcome:
Ansible roles are executed on the remote system
Foreman and Proxy versions:
foreman-3.0.1-1.el8.noarch
foreman-proxy-3.0.1-1.el8.noarch
Distribution and version:
CentOS Stream 8
Other relevant data:
2021-12-14T19:39:18 [E] error while dispatching request to runner bd61b241-d120-459f-9d21-85b56518018b:TypeError no implicit conversion of nil into String:
/usr/share/gems/gems/smart_proxy_ansible-3.2.1/lib/smart_proxy_ansible/runner/ansible_runner.rb:34:in `basename'
/usr/share/gems/gems/smart_proxy_ansible-3.2.1/lib/smart_proxy_ansible/runner/ansible_runner.rb:34:in `refresh'
/usr/share/gems/gems/smart_proxy_dynflow-0.5.2/lib/smart_proxy_dynflow/runner/base.rb:21:in `run_refresh'
/usr/share/gems/gems/smart_proxy_dynflow-0.5.2/lib/smart_proxy_dynflow/runner/dispatcher.rb:40:in `refresh_runner'
/usr/share/gems/gems/dynflow-1.5.0/lib/dynflow/actor.rb:13:in `on_message'
Hi,
this usually indicates some issue with ansible-runner. Could you bump log level to debug in /etc/foreman-proxy/settings.yml, restart foreman-proxy, try running a job again and watching /var/log/foreman-proxy/proxy.log? Hopefully something relevant could get captured there.
2021-12-15T11:30:40 [D] Executor heartbeat
2021-12-15T11:30:49 [D] accept: 192.168.xxx.xxx:34062
2021-12-15T11:30:49 [D] Rack::Handler::WEBrick is invoked.
2021-12-15T11:30:49 da3da508 [I] Started GET /dynflow/tasks/count state=running
2021-12-15T11:30:49 da3da508 [D] verifying remote client 192.168.xxx.xxx against trusted_hosts ["foreman.abc.ab"]
2021-12-15T11:30:49 da3da508 [I] Finished GET /dynflow/tasks/count with 200 (22.73 ms)
2021-12-15T11:30:50 [D] close: 192.168.xxx.xxx:34062
2021-12-15T11:30:51 [D] accept: 192.168.xxx.xxx:34066
2021-12-15T11:30:51 [D] Rack::Handler::WEBrick is invoked.
2021-12-15T11:30:51 da3da508 [I] Started POST /dynflow/tasks/launch
2021-12-15T11:30:51 da3da508 [D] verifying remote client 192.168.xxx.xxx against trusted_hosts ["foreman.abc.ab"]
2021-12-15T11:30:51 da3da508 [D] ExecutionPlan 522c13dc-c065-4696-8f21-1317ecb5ccb3 pending >> planning
2021-12-15T11:30:51 da3da508 [D] Step 522c13dc-c065-4696-8f21-1317ecb5ccb3: 1 pending >> running in phase Plan Proxy::Dynflow::Action::SingleRunnerBatch
2021-12-15T11:30:51 da3da508 [D] ExecutionPlan ee4443d8-7fc2-4f5a-8110-26797eb11e74 pending >> planning
2021-12-15T11:30:51 da3da508 [D] Step ee4443d8-7fc2-4f5a-8110-26797eb11e74: 1 pending >> running in phase Plan Proxy::Dynflow::Action::OutputCollector
2021-12-15T11:30:51 da3da508 [D] Step ee4443d8-7fc2-4f5a-8110-26797eb11e74: 1 running >> success in phase Plan Proxy::Dynflow::Action::OutputCollector
2021-12-15T11:30:51 da3da508 [D] ExecutionPlan ee4443d8-7fc2-4f5a-8110-26797eb11e74 planning >> planned
2021-12-15T11:30:51 [D] ExecutionPlan ee4443d8-7fc2-4f5a-8110-26797eb11e74 planned >> running
2021-12-15T11:30:51 da3da508 [D] ExecutionPlan d3ebe431-d0a0-408f-9bfe-89b2af3a17de pending >> planning
2021-12-15T11:30:51 da3da508 [D] Step d3ebe431-d0a0-408f-9bfe-89b2af3a17de: 1 pending >> running in phase Plan Proxy::Dynflow::Action::BatchRunner
2021-12-15T11:30:51 da3da508 [D] Step d3ebe431-d0a0-408f-9bfe-89b2af3a17de: 1 running >> success in phase Plan Proxy::Dynflow::Action::BatchRunner
2021-12-15T11:30:51 da3da508 [D] ExecutionPlan d3ebe431-d0a0-408f-9bfe-89b2af3a17de planning >> planned
2021-12-15T11:30:51 [D] Step ee4443d8-7fc2-4f5a-8110-26797eb11e74: 2 pending >> running in phase Run Proxy::Dynflow::Action::OutputCollector
2021-12-15T11:30:51 da3da508 [D] Step ee4443d8-7fc2-4f5a-8110-26797eb11e74: 2 running >> suspended in phase Run Proxy::Dynflow::Action::OutputCollector
2021-12-15T11:30:51 [D] ExecutionPlan d3ebe431-d0a0-408f-9bfe-89b2af3a17de planned >> running
2021-12-15T11:30:51 da3da508 [D] Step 522c13dc-c065-4696-8f21-1317ecb5ccb3: 4 pending >> running in phase Plan Proxy::Dynflow::Action::BatchCallback
2021-12-15T11:30:51 da3da508 [D] Step 522c13dc-c065-4696-8f21-1317ecb5ccb3: 4 running >> success in phase Plan Proxy::Dynflow::Action::BatchCallback
2021-12-15T11:30:51 da3da508 [D] Step 522c13dc-c065-4696-8f21-1317ecb5ccb3: 1 running >> success in phase Plan Proxy::Dynflow::Action::SingleRunnerBatch
2021-12-15T11:30:51 da3da508 [D] ExecutionPlan 522c13dc-c065-4696-8f21-1317ecb5ccb3 planning >> planned
2021-12-15T11:30:51 [D] Step d3ebe431-d0a0-408f-9bfe-89b2af3a17de: 2 pending >> running in phase Run Proxy::Dynflow::Action::BatchRunner
2021-12-15T11:30:51 da3da508 [I] Finished POST /dynflow/tasks/launch with 200 (99.1 ms)
2021-12-15T11:30:51 [D] start runner 0c742c2b-d174-41b9-97df-055b9c0b74eb
2021-12-15T11:30:51 [D] [foreman_ansible] - Running command '{} ansible-runner run /tmp/d20211215-57606-1ktmbq7 -p playbook.yml --cmdline --check -vvv'
2021-12-15T11:30:51 [D] refresh runner 0c742c2b-d174-41b9-97df-055b9c0b74eb
2021-12-15T11:30:51 [D] refreshing runner
2021-12-15T11:30:51 [D] ExecutionPlan 522c13dc-c065-4696-8f21-1317ecb5ccb3 planned >> running
2021-12-15T11:30:52 [D] Step 522c13dc-c065-4696-8f21-1317ecb5ccb3: 2 pending >> running in phase Run Proxy::Dynflow::Action::SingleRunnerBatch
2021-12-15T11:30:52 da3da508 [D] Step d3ebe431-d0a0-408f-9bfe-89b2af3a17de: 2 running >> suspended in phase Run Proxy::Dynflow::Action::BatchRunner
2021-12-15T11:30:52 da3da508 [D] Step 522c13dc-c065-4696-8f21-1317ecb5ccb3: 2 running >> suspended in phase Run Proxy::Dynflow::Action::SingleRunnerBatch
2021-12-15T11:30:52 [D] close: 192.168.xxx.xxx:34066
2021-12-15T11:30:52 [D] planning to refresh 0c742c2b-d174-41b9-97df-055b9c0b74eb
2021-12-15T11:30:53 [D] Ticker ticking for 1 events
2021-12-15T11:30:53 [D] refresh runner 0c742c2b-d174-41b9-97df-055b9c0b74eb
2021-12-15T11:30:53 [D] refreshing runner
2021-12-15T11:30:53 [D] planning to refresh 0c742c2b-d174-41b9-97df-055b9c0b74eb
2021-12-15T11:30:53 [E] error while dispatching request to runner 0c742c2b-d174-41b9-97df-055b9c0b74eb:TypeError no implicit conversion of nil into String:
/usr/share/gems/gems/smart_proxy_ansible-3.2.1/lib/smart_proxy_ansible/runner/ansible_runner.rb:34:in `basename'
/usr/share/gems/gems/smart_proxy_ansible-3.2.1/lib/smart_proxy_ansible/runner/ansible_runner.rb:34:in `refresh'
/usr/share/gems/gems/smart_proxy_dynflow-0.5.2/lib/smart_proxy_dynflow/runner/base.rb:21:in `run_refresh'
/usr/share/gems/gems/smart_proxy_dynflow-0.5.2/lib/smart_proxy_dynflow/runner/dispatcher.rb:40:in `refresh_runner'
/usr/share/gems/gems/dynflow-1.5.0/lib/dynflow/actor.rb:13:in `on_message'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/context.rb:46:in `on_envelope'
/usr/share/gems/gems/smart_proxy_dynflow-0.5.2/lib/smart_proxy_dynflow/runner/dispatcher.rb:24:in `on_envelope'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/executes_context.rb:7:in `on_envelope'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/usr/share/gems/gems/dynflow-1.5.0/lib/dynflow/actor.rb:122:in `on_envelope'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/awaits.rb:15:in `on_envelope'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/sets_results.rb:14:in `on_envelope'
/usr/share/gems/gems/dynflow-1.5.0/lib/dynflow/actor.rb:56:in `on_envelope'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/buffer.rb:38:in `process_envelope'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/buffer.rb:31:in `process_envelopes?'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/buffer.rb:20:in `on_envelope'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/termination.rb:55:in `on_envelope'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/removes_child.rb:10:in `on_envelope'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/sets_results.rb:14:in `on_envelope'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/core.rb:162:in `process_envelope'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/core.rb:96:in `block in on_envelope'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/core.rb:119:in `block (2 levels) in schedule_execution'
/usr/share/gems/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:41:in `block in synchronize'
/usr/share/gems/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:41:in `synchronize'
/usr/share/gems/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:41:in `synchronize'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/core.rb:116:in `block in schedule_execution'
/usr/share/gems/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent/executor/serialized_execution.rb:18:in `call'
/usr/share/gems/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent/executor/serialized_execution.rb:96:in `work'
/usr/share/gems/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent/executor/serialized_execution.rb:77:in `block in call_job'
/usr/share/gems/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:353:in `run_task'
/usr/share/gems/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:342:in `block (3 levels) in create_worker'
/usr/share/gems/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:325:in `loop'
/usr/share/gems/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:325:in `block (2 levels) in create_worker'
/usr/share/gems/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:324:in `catch'
/usr/share/gems/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:324:in `block in create_worker'
/usr/share/gems/gems/logging-2.3.0/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
2021-12-15T11:30:53 [D] closing session for command [0c742c2b-d174-41b9-97df-055b9c0b74eb],0 actors left
2021-12-15T11:30:53 [D] terminate 0c742c2b-d174-41b9-97df-055b9c0b74eb
2021-12-15T11:30:53 [D] Step d3ebe431-d0a0-408f-9bfe-89b2af3a17de: 2 got event #<Proxy::Dynflow::Runner::Update:0x000055d6781c8be0>
2021-12-15T11:30:53 [D] Step d3ebe431-d0a0-408f-9bfe-89b2af3a17de: 2 suspended >> running in phase Run Proxy::Dynflow::Action::BatchRunner
2021-12-15T11:30:53 da3da508 [D] Step d3ebe431-d0a0-408f-9bfe-89b2af3a17de: 2 running >> success in phase Run Proxy::Dynflow::Action::BatchRunner
2021-12-15T11:30:53 [D] Step d3ebe431-d0a0-408f-9bfe-89b2af3a17de: 3 pending >> running in phase Finalize Proxy::Dynflow::Action::BatchRunner
2021-12-15T11:30:53 da3da508 [E] Script execution failed
2021-12-15T11:30:53 da3da508 [D] Step d3ebe431-d0a0-408f-9bfe-89b2af3a17de: 3 running >> error in phase Finalize Proxy::Dynflow::Action::BatchRunner
2021-12-15T11:30:53 [D] ExecutionPlan d3ebe431-d0a0-408f-9bfe-89b2af3a17de running >> stopped
2021-12-15T11:30:54 [D] Ticker ticking for 1 events
2021-12-15T11:30:54 [D] accept: 192.168.xxx.xxx:34072
2021-12-15T11:30:54 [D] Rack::Handler::WEBrick is invoked.
2021-12-15T11:30:54 e0ff68ad [I] Started GET /dynflow/tasks/ee4443d8-7fc2-4f5a-8110-26797eb11e74/status
2021-12-15T11:30:54 e0ff68ad [D] verifying remote client 192.168.xxx.xxx against trusted_hosts ["foreman.abc.ab"]
2021-12-15T11:30:54 e0ff68ad [I] Finished GET /dynflow/tasks/ee4443d8-7fc2-4f5a-8110-26797eb11e74/status with 200 (19.63 ms)
2021-12-15T11:30:54 [D] close: 192.168.xxx.xxx:34072
2021-12-15T11:30:55 [D] Executor heartbeat
2021-12-15T11:30:57 [D] accept: 192.168.xxx.xxx:34086
2021-12-15T11:30:57 [D] Rack::Handler::WEBrick is invoked.
2021-12-15T11:30:57 c9612fa2 [I] Started GET /dynflow/tasks/ee4443d8-7fc2-4f5a-8110-26797eb11e74/status
2021-12-15T11:30:57 c9612fa2 [D] verifying remote client 192.168.xxx.xxx against trusted_hosts ["foreman.abc.ab"]
2021-12-15T11:30:57 c9612fa2 [I] Finished GET /dynflow/tasks/ee4443d8-7fc2-4f5a-8110-26797eb11e74/status with 200 (7.76 ms)
2021-12-15T11:30:57 [D] close: 192.168.xxx.xxx:34086
2021-12-15T11:30:59 [D] accept: 192.168.xxx.xxx:34092
2021-12-15T11:30:59 [D] Rack::Handler::WEBrick is invoked.
2021-12-15T11:30:59 045879a8 [I] Started GET /dynflow/tasks/ee4443d8-7fc2-4f5a-8110-26797eb11e74/status
2021-12-15T11:30:59 045879a8 [D] verifying remote client 192.168.xxx.xxx against trusted_hosts ["foreman.abc.ab"]
2021-12-15T11:30:59 045879a8 [I] Finished GET /dynflow/tasks/ee4443d8-7fc2-4f5a-8110-26797eb11e74/status with 200 (7.24 ms)
2021-12-15T11:30:59 [D] close: 192.168.xxx.xxx:34092
2021-12-15T11:31:00 [D] accept: 192.168.xxx.xxx:34096
2021-12-15T11:31:00 [D] Rack::Handler::WEBrick is invoked.
2021-12-15T11:31:00 5eb3190c [I] Started GET /dynflow/tasks/ee4443d8-7fc2-4f5a-8110-26797eb11e74/status
2021-12-15T11:31:00 5eb3190c [D] verifying remote client 192.168.xxx.xxx against trusted_hosts ["foreman.abc.ab"]
2021-12-15T11:31:00 5eb3190c [I] Finished GET /dynflow/tasks/ee4443d8-7fc2-4f5a-8110-26797eb11e74/status with 200 (8.19 ms)
2021-12-15T11:31:00 [D] close: 192.168.xxx.xxx:34096
2021-12-15T11:31:02 [D] Step 522c13dc-c065-4696-8f21-1317ecb5ccb3: 2 got event Dynflow::Action::WithPollingSubPlans::Poll
2021-12-15T11:31:02 [D] Step 522c13dc-c065-4696-8f21-1317ecb5ccb3: 2 suspended >> running in phase Run Proxy::Dynflow::Action::SingleRunnerBatch
2021-12-15T11:31:02 da3da508 [D] Step 522c13dc-c065-4696-8f21-1317ecb5ccb3: 2 running >> suspended in phase Run Proxy::Dynflow::Action::SingleRunnerBatch
2021-12-15T11:31:02 [D] accept: 192.168.xxx.xxx:34106
2021-12-15T11:31:03 [D] Rack::Handler::WEBrick is invoked.
2021-12-15T11:31:03 51955e41 [I] Started GET /dynflow/tasks/ee4443d8-7fc2-4f5a-8110-26797eb11e74/status
2021-12-15T11:31:03 51955e41 [D] verifying remote client 192.168.xxx.xxx against trusted_hosts ["foreman.abc.ab"]
2021-12-15T11:31:03 51955e41 [I] Finished GET /dynflow/tasks/ee4443d8-7fc2-4f5a-8110-26797eb11e74/status with 200 (8.23 ms)
2021-12-15T11:31:03 [D] close: 192.168.xxx.xxx:34106
2021-12-15T11:31:04 [D] accept: 192.168.xxx.xxx:34110
2021-12-15T11:31:04 [D] Rack::Handler::WEBrick is invoked.
2021-12-15T11:31:04 b123bf38 [I] Started GET /dynflow/tasks/ee4443d8-7fc2-4f5a-8110-26797eb11e74/status
2021-12-15T11:31:04 b123bf38 [D] verifying remote client 192.168.xxx.xxx against trusted_hosts ["foreman.abc.ab"]
2021-12-15T11:31:04 b123bf38 [I] Finished GET /dynflow/tasks/ee4443d8-7fc2-4f5a-8110-26797eb11e74/status with 200 (7.45 ms)
2021-12-15T11:31:04 [D] close: 192.168.xxx.xxx:34110
If you need any other information, no problem.
The mentioned /tmp/d20211215-57606-1ktmbq7 is created during execution of the job, and directly deleted again. ( shown by
while true; do ls -ltr /tmp/; sleep 1; clear; done
From the debug logs it seems it is trying to run in check mode, but the right flags are not passed to ansible-runner properly. Is it your intent to run it in check mode?
