Foreman does not respect ansible timeout

Support
,
#1

Problem:
Ansible roles are launched right after host is provisioned from bare metal - basically when there is no ssh on it, task fails:

TASK [Gathering Facts] *********************************************************
fatal: [mac001a0000072d.krtech.loc]: UNREACHABLE! => {"changed": false, "msg": "Failed to connect to the host via ssh: ssh: connect to host mac001a0000072d.krtech.loc port 22: Connection refused\r\n", "unreachable": true}
	to retry, use: --limit @/tmp/d20180222-4943-14j50jk/foreman-playbook-4aef7ef0-65b9-41d1-9b9d-77566b0dd728.retry

This is what it looks like in production.log:

2018-02-22 17:57:48 caf1ec88 [app] [I] Started GET "/unattended/built?token=71580466-0c0f-4570-ba75-e4cfa77991e2" for 10.0.152.12 at 2018-02-22 17:57:48 +0300
2018-02-22 17:57:48 caf1ec88 [app] [I] Processing by UnattendedController#built as TEXT
2018-02-22 17:57:48 caf1ec88 [app] [I]   Parameters: {"token"=>"71580466-0c0f-4570-ba75-e4cfa77991e2"}
2018-02-22 17:57:48 caf1ec88 [app] [I] Current user: foreman_api_admin (administrator)
2018-02-22 17:57:48 caf1ec88 [app] [I] unattended: mac001a0000072d.krtech.loc is Built!
2018-02-22 17:57:49 caf1ec88 [templates] [I] Rendering template 'PXEGrub2 default local boot'
2018-02-22 17:57:49 caf1ec88 [templates] [I] Rendering template 'pxegrub2_chainload'
2018-02-22 17:57:49 caf1ec88 [app] [I] Deploying TFTP PXEGrub2 configuration for mac001a0000072d.krtech.loc
2018-02-22 17:57:49 caf1ec88 [templates] [I] Rendering template 'PXELinux default local boot'
2018-02-22 17:57:49 caf1ec88 [templates] [I] Rendering template 'pxelinux_chainload'
2018-02-22 17:57:49 caf1ec88 [app] [I] Deploying TFTP PXELinux configuration for mac001a0000072d.krtech.loc
2018-02-22 17:57:49 caf1ec88 [templates] [I] Rendering template 'PXEGrub default local boot'
2018-02-22 17:57:49 caf1ec88 [templates] [I] Rendering template 'pxegrub_chainload'
2018-02-22 17:57:49 caf1ec88 [app] [I] Deploying TFTP PXEGrub configuration for mac001a0000072d.krtech.loc
2018-02-22 17:57:49 caf1ec88 [app] [I] Delete the autosign entry for mac001a0000072d.krtech.loc
2018-02-22 17:57:49 caf1ec88 [app] [I] Processed 4 tasks from queue 'Host::Managed Main', completed 4/4
2018-02-22 17:57:49 caf1ec88 [app] [I] Task for Ansible roles on mac001a0000072d.krtech.loc before_provision: /tasks/2c6dec0e-6028-4810-bcdf-971e462ecb0b.
2018-02-22 17:57:49 caf1ec88 [app] [I] Completed 201 Created in 935ms (ActiveRecord: 67.8ms)

Expected outcome:
Ansible roles will launch after provision, based on timeout specified in settings

Foreman and Proxy versions:
1.16

Foreman and Proxy plugin versions:

foreman-tasks 0.10.9
foreman_ansible 1.4.6
foreman_dhcp_browser 0.0.7
foreman_discovery 10.0.0
foreman_remote_execution 1.3.3
foreman_setup 5.0.0

Other relevant data:
puppet is disabled in provisioning templates (i need a clean system)

#2

Thanks for the report!

Can you set log_level to DEBUG on /etc/foreman-proxy/settings.yaml and try to do this again?

There should be some logs on /var/log/foreman-proxy/proxy.log where you could see the parameters sent to ansible. What this setting is supposed to do is to set the ansible-playbook -T parameter.

#3

Ok :slight_smile: But one thing - there’s nothing in proxy’s log, everything is in foremans production log. I’m running playbooks on the same machine foreman resides in.

2018-02-25 02:30:57 3c1ced0a [app] [D] Task 'Deploy TFTP PXEGrub2 config for mac001a0000072d.krtech.loc' *completed*
2018-02-25 02:30:57 3c1ced0a [app] [D] Task 'Deploy TFTP PXELinux config for mac001a0000072d.krtech.loc' *completed*
2018-02-25 02:30:57 3c1ced0a [app] [D] Task 'Deploy TFTP PXEGrub config for mac001a0000072d.krtech.loc' *completed*
2018-02-25 02:30:57 3c1ced0a [app] [D] Task 'Delete PuppetCA autosign entry for mac001a0000072d.krtech.loc' *completed*
2018-02-25 02:30:57 3c1ced0a [dynflow] [D] ExecutionPlan 49630ea4-6b8c-4225-844f-b96ad1cbab37      pending >>  planning
2018-02-25 02:30:57 3c1ced0a [dynflow] [D]          Step 49630ea4-6b8c-4225-844f-b96ad1cbab37: 1   pending >>   running in phase     Plan Actions::ForemanAnsible::P$2018-02-25 02:30:57 3c1ced0a [dynflow] [D]          Step 49630ea4-6b8c-4225-844f-b96ad1cbab37: 2   pending >>   running in phase     Plan Actions::ProxyAction
2018-02-25 02:30:57 3c1ced0a [dynflow] [D]          Step 49630ea4-6b8c-4225-844f-b96ad1cbab37: 2   running >>   success in phase     Plan Actions::ProxyAction
2018-02-25 02:30:57 3c1ced0a [dynflow] [D]          Step 49630ea4-6b8c-4225-844f-b96ad1cbab37: 1   running >>   success in phase     Plan Actions::ForemanAnsible::P$2018-02-25 02:30:57 3c1ced0a [dynflow] [D] ExecutionPlan 49630ea4-6b8c-4225-844f-b96ad1cbab37     planning >>   planned
2018-02-25 02:30:57 3c1ced0a [app] [I] Task for Ansible roles on mac001a0000072d.krtech.loc before_provision: /tasks/b269a378-9c78-4f93-a17d-f9c3e168c5de.
2018-02-25 02:30:57 3c1ced0a [app] [D] custom hook before_provision on mac001a0000072d.krtech.loc will be executed if defined.
2018-02-25 02:30:57 3c1ced0a [notifications] [D] Notification event: Hosts::BuildCompleted - checking for notifications
2018-02-25 02:30:57  [dynflow] [D] ExecutionPlan 49630ea4-6b8c-4225-844f-b96ad1cbab37      planned >>   running
2018-02-25 02:30:57  [dynflow] [D]          Step 49630ea4-6b8c-4225-844f-b96ad1cbab37: 3   pending >>   running in phase      Run Actions::ProxyAction
2018-02-25 02:30:57 3c1ced0a [app] [I] Completed 201 Created in 1115ms (ActiveRecord: 66.7ms)
2018-02-25 02:30:57 aa49033e [app] [I] Started GET "/notification_recipients" for 10.150.250.81 at 2018-02-25 02:30:57 +0300
2018-02-25 02:30:57 aa49033e [app] [I] Processing by NotificationRecipientsController#index as JSON
2018-02-25 02:30:57 aa49033e [app] [I] Current user: admin (administrator)
2018-02-25 02:30:57 aa49033e [app] [D] Setting current user thread-local variable to admin
2018-02-25 02:30:57 aa49033e [notifications] [D] Cache Miss: notification, writing cache for notification-4
2018-02-25 02:30:57 aa49033e [notifications] [D] Expiring notification cache notification-4 in 3600 seconds
2018-02-25 02:30:57 aa49033e [app] [D] Body: {"notifications":[]}
2018-02-25 02:30:57 aa49033e [app] [I] Completed 200 OK in 16ms (Views: 0.2ms | ActiveRecord: 2.6ms)
2018-02-25 02:30:58  [dynflow] [D]          Step 49630ea4-6b8c-4225-844f-b96ad1cbab37: 3   running >> suspended in phase      Run Actions::ProxyAction
2018-02-25 02:30:59 0dc196b7 [app] [I] Started POST "/api/v2/reports" for ::1 at 2018-02-25 02:30:59 +0300
2018-02-25 02:30:59 0dc196b7 [app] [I] Processing by Api::V2::ReportsController#create as JSON
2018-02-25 02:30:59 0dc196b7 [app] [I]   Parameters: {"report"=>"[FILTERED]", "apiv"=>"v2"}
2018-02-25 02:30:59 0dc196b7 [app] [D] Examining client certificate to extract dn and sans
2018-02-25 02:30:59 0dc196b7 [app] [D] Client sent certificate with subject 'deploy.krtech.loc' and subject alt names '["deploy.krtech.loc", "puppet", "puppet.krtec$$"deploy.krtech.loc"]
2018-02-25 02:30:59 0dc196b7 [app] [I] Current user: foreman_api_admin (administrator)
2018-02-25 02:30:59 0dc196b7 [app] [D] Setting current user thread-local variable to foreman_api_admin
2018-02-25 02:30:59 0dc196b7 [app] [D] Processing report: {"reported_at"=>"2018-02-25 02:30:59 841840", "metrics"=>{"time"=>{"total"=>0}}, "host"=>"mac001a0000072d.$2018-02-25 02:31:00 0dc196b7 [app] [D] no owner or recipients for alert on mac001a0000072d.krtech.loc
2018-02-25 02:31:00 0dc196b7 [app] [I] Imported report for mac001a0000072d.krtech.loc in 0.07 seconds, status refreshed in 0.02 seconds
2018-02-25 02:31:00 0dc196b7 [app] [I]   Rendered api/v2/reports/create.json.rabl (13.5ms)
2018-02-25 02:31:00 0dc196b7 [app] [D] Body: {"metrics":{"time":{"total":0}},"created_at":"2018-02-24 23:30:59 UTC","updated_at":"2018-02-24 23:30:59 UTC","id":139,$2018-02-25 02:31:00 0dc196b7 [app] [I] Completed 201 Created in 137ms (Views: 21.0ms | ActiveRecord: 26.9ms)
2018-02-25 02:31:00 1d19a617 [app] [I] Started POST "/api/v2/reports" for ::1 at 2018-02-25 02:31:00 +0300
2018-02-25 02:31:00 1d19a617 [app] [I] Processing by Api::V2::ReportsController#create as JSON
2018-02-25 02:31:00 1d19a617 [app] [I]   Parameters: {"report"=>"[FILTERED]", "apiv"=>"v2"}
2018-02-25 02:31:00 1d19a617 [app] [D] Examining client certificate to extract dn and sans
2018-02-25 02:31:00 1d19a617 [app] [D] Client sent certificate with subject 'deploy.krtech.loc' and subject alt names '["deploy.krtech.loc", "puppet", "puppet.krtec$2018-02-25 02:31:00 1d19a617 [app] [D] Verifying request from ["deploy.krtech.loc", "puppet", "puppet.krtech.loc"] against ["deploy.krtech.loc", "localhost", "deplo$2018-02-25 02:31:00 1d19a617 [app] [I] Current user: foreman_api_admin (administrator)
2018-02-25 02:31:00 1d19a617 [app] [D] Setting current user thread-local variable to foreman_api_admin
2018-02-25 02:31:00 1d19a617 [app] [D] Processing report: {"reported_at"=>"2018-02-25 02:31:00 075129", "metrics"=>{"time"=>{"total"=>1}}, "host"=>"mac001a0000072d.$2018-02-25 02:31:00 1d19a617 [app] [D] no owner or recipients for alert on mac001a0000072d.krtech.loc
2018-02-25 02:31:00 1d19a617 [app] [D] Body: {"metrics":{"time":{"total":1}},"created_at":"2018-02-24 23:31:00 UTC","updated_at":"2018-02-24 23:31:00 UTC","id":140,$2018-02-25 02:31:00 1d19a617 [app] [I] Completed 201 Created in 96ms (Views: 15.4ms | ActiveRecord: 19.5ms)
2018-02-25 02:31:01 5841fea7 [app] [I] Started POST "/foreman_tasks/api/tasks/callback" for 10.0.152.10 at 2018-02-25 02:31:01 +0300
2018-02-25 02:31:01 5841fea7 [app] [I] Processing by ForemanTasks::Api::TasksController#callback as */*
2018-02-25 02:31:01 5841fea7 [app] [I]   Parameters: {"callback"=>{"task_id"=>"b269a378-9c78-4f93-a17d-f9c3e168c5de", "step_id"=>3}, "data"=>{"result"=>[{"output_ty$2018-02-25 02:31:01 5841fea7 [app] [D] Examining client certificate to extract dn and sans
2018-02-25 02:31:01 5841fea7 [app] [D] Client sent certificate with subject 'deploy.krtech.loc' and subject alt names '["deploy.krtech.loc", "puppet", "puppet.krtec$2018-02-25 02:31:01 5841fea7 [app] [D] Verifying request from ["deploy.krtech.loc", "puppet", "puppet.krtech.loc"] against ["deploy.krtech.loc", "localhost", "deplo$2018-02-25 02:31:01 5841fea7 [app] [I] Current user: foreman_api_admin (administrator)
2018-02-25 02:31:01 5841fea7 [app] [D] Setting current user thread-local variable to foreman_api_admin
2018-02-25 02:31:01 5841fea7 [app] [D] Body: {"message":"processing"}
2018-02-25 02:31:01 5841fea7 [app] [I] Completed 200 OK in 12ms (Views: 0.3ms | ActiveRecord: 1.6ms)
2018-02-25 02:31:01  [dynflow] [D]          Step 49630ea4-6b8c-4225-844f-b96ad1cbab37: 3 got event #<Actions::ProxyAction::CallbackData:0x007f01582f46e8>
2018-02-25 02:31:01  [dynflow] [D]          Step 49630ea4-6b8c-4225-844f-b96ad1cbab37: 3 suspended >>   running in phase      Run Actions::ProxyAction
2018-02-25 02:31:01  [dynflow] [D]          Step 49630ea4-6b8c-4225-844f-b96ad1cbab37: 3   running >>   success in phase      Run Actions::ProxyAction
2018-02-25 02:31:01  [dynflow] [D]          Step 49630ea4-6b8c-4225-844f-b96ad1cbab37: 4   pending >>   running in phase Finalize Actions::ForemanAnsible::PlayHostR$
2018-02-25 02:31:01  [background] [E] Playbook execution failed
2018-02-25 02:31:01  [dynflow] [D]          Step 49630ea4-6b8c-4225-844f-b96ad1cbab37: 4   running >>     error in phase Finalize Actions::ForemanAnsible::PlayHostR$2018-02-25 02:31:01  [dynflow] [D] ExecutionPlan 49630ea4-6b8c-4225-844f-b96ad1cbab37      running >>    paused
2018-02-25 02:31:01  [dynflow] [D] ExecutionPlan 49630ea4-6b8c-4225-844f-b96ad1cbab37       paused >>   stopped
2018-02-25 02:31:05  [app] [I] Current user: foreman_admin (administrator)
2018-02-25 02:31:05  [app] [D] Setting current user thread-local variable to foreman_admin
2018-02-25 02:31:05  [app] [D] Setting current user thread-local variable to nil
2018-02-25 02:31:05  [app] [I] Current user: foreman_admin (administrator)
2018-02-25 02:31:05  [app] [D] Setting current user thread-local variable to foreman_admin
2018-02-25 02:31:05  [app] [D] Setting current user thread-local variable to nil
2018-02-25 02:31:05  [app] [D] Registering 6 assets for plugin foreman-tasks precompilation
2018-02-25 02:31:05  [app] [I] Current user: foreman_admin (administrator)
2018-02-25 02:31:05  [app] [D] Setting current user thread-local variable to foreman_admin
2018-02-25 02:31:05  [app] [D] Setting current user thread-local variable to nil
2018-02-25 02:31:05  [app] [D] Registering 2 assets for plugin foreman_ansible precompilation
2018-02-25 02:31:06  [app] [I] Current user: foreman_admin (administrator)
2018-02-25 02:31:06  [app] [D] Setting current user thread-local variable to foreman_admin
2018-02-25 02:31:06  [app] [D] Setting current user thread-local variable to nil
2018-02-25 02:31:06  [app] [I] Current user: foreman_admin (administrator)

This is what could be found in foremans webui task logs:

[WARNING]: SSL verification of https://localhost:443 disabled

PLAY [all] *********************************************************************

TASK [Gathering Facts] *********************************************************
fatal: [mac001a0000072d.krtech.loc]: UNREACHABLE! => {“changed”: false, “msg”: “Failed to connect to the host via ssh: ssh: connect to host mac001a0000072d.krtech.loc port 22: Connection refused\r\n”, “unreachable”: true}
to retry, use: --limit @/tmp/foreman-playbook-6deb1d9f-50db-4f95-8fde-a276196b9a66.retry

PLAY RECAP *********************************************************************
mac001a0000072d.krtech.loc : ok=0 changed=0 unreachable=1 failed=0

#4

I must add that when manually launched roles work just fine.

#5

Btw, i think that -T parameter manages the connection timeout - a time to wait for reply from server, when ssh service is not running we get connection refused, so playbook fails.
Delay of running asible task should be set via foreman, or somehow caled later… For now i set an alias for ansible-playbook to always run with -T and set timeout parameter in ansible.cfg - i gained nothing. For now i’m thinking to substitute ansible-playbook command with shell script providing sleep before execution.

#6

Yep, my theory proved to be right - once i added sleep to bash script calling ansible - everything provisioned right. Sooo… What i did - i substituted system-wide ansible-playbook with my script, which is not correct, can you provide some fix to the foreman-ansible plugin?

#7

Which script? Are you talking about json_inventory.sh ?