Ansible roles are not starting automatically after provisioning

obol89 · November 18, 2021, 2:26pm

Problem:
After upgrading to 3.1.0-rc1 Ansible roles are not starting automatically after successful provisioning. They are working fine when we start them manually i.e. go to host and “Run Ansible roles”.
I didn’t find any settings or hook for that. Also, I didn’t notice any errors in the logs.

Expected outcome:
Ansible roles should run automatically after provisioning.

Foreman and Proxy versions:
3.1.0-rc1

Foreman and Proxy plugin versions:
foreman-tasks 5.1.1
foreman_ansible 6.4.1
foreman_default_hostgroup 6.0.0
foreman_discovery 18.0.4
foreman_hooks 0.3.17
foreman_kubevirt 0.1.9
foreman_openscap 5.1.0
foreman_puppet 2.0.0.alpha.2
foreman_remote_execution 4.8.0
foreman_setup 7.0.0
foreman_snapshot_management 2.0.1
foreman_templates 9.1.0
katello 4.2.1

Distribution and version:
CentOS Linux release 7.9.2009

obol89 · November 22, 2021, 9:40am

Does anyone have any ideas what might be the issue or what else to check?

aruzicka · November 22, 2021, 12:40pm

Hi,
could you bump the log level to debug, try provisioning a host again and then post production.log from that time?

obol89 · November 22, 2021, 1:36pm

I’ve changed the log level to debug and I’ve tried to provision the host again with two ansible roles assigned to it.

2021-11-22T07:26:01 [I|app|05d03287] Started GET "/unattended/finish?token=[FILTERED]&static=true&url=http%3A%2F%2Fchd-prd-foreman02.companydomain.com%3A8000" for 10.9.64.196 at 2021-11-22 07:26:01 -0600
2021-11-22T07:26:01 [I|app|05d03287] Processing by UnattendedController#host_template as TEXT
2021-11-22T07:26:01 [I|app|05d03287]   Parameters: {"token"=>"[FILTERED]", "static"=>"true", "url"=>"http://chd-prd-foreman02.companydomain.com:8000", "kind"=>"finish", "unattended"=>{}}
2021-11-22T07:26:01 [D|app|05d03287] Found chd-dev-vptest01.companydomain.com
2021-11-22T07:26:01 [D|tax|05d03287] Current organization set to My Organization
2021-11-22T07:26:01 [D|tax|05d03287] Current location set to America/CHD
2021-11-22T07:26:01 [D|tax|05d03287] Current location set to none
2021-11-22T07:26:01 [D|tax|05d03287] Current organization set to none
2021-11-22T07:26:01 [I|app|05d03287]   Rendering text template
2021-11-22T07:26:01 [I|app|05d03287]   Rendered text template (Duration: 0.0ms | Allocations: 1)
2021-11-22T07:26:01 [I|app|05d03287] Completed 200 OK in 99ms (Views: 0.8ms | ActiveRecord: 19.3ms | Allocations: 40710)
2021-11-22T07:26:01 [I|app|53692755] Started GET "/unattended/built?token=[FILTERED]&url=http%3A%2F%2Fchd-prd-foreman02.companydomain.com%3A8000" for 10.9.64.196 at 2021-11-22 07:26:01 -0600
2021-11-22T07:26:01 [I|app|53692755] Processing by UnattendedController#built as TEXT
2021-11-22T07:26:01 [I|app|53692755]   Parameters: {"token"=>"[FILTERED]", "url"=>"http://chd-prd-foreman02.companydomain.com:8000", "unattended"=>{}}
2021-11-22T07:26:01 [D|app|53692755] Found chd-dev-vptest01.companydomain.com
2021-11-22T07:26:01 [I|app|53692755] unattended: chd-dev-vptest01.companydomain.com is built!
2021-11-22T07:26:01 [D|tax|53692755] Current organization set to My Organization
2021-11-22T07:26:01 [D|tax|53692755] Current location set to America/CHD
2021-11-22T07:26:01 [D|tax|53692755] Current location set to none
2021-11-22T07:26:01 [D|tax|53692755] Current organization set to none
2021-11-22T07:26:01 [D|app|53692755] Enqueued task 'Deploy TFTP PXELinux config for chd-dev-vptest01.companydomain.com' to 'Host::Managed Main' queue
2021-11-22T07:26:01 [D|app|53692755] Enqueued task 'Deploy TFTP PXEGrub2 config for chd-dev-vptest01.companydomain.com' to 'Host::Managed Main' queue
2021-11-22T07:26:01 [D|app|53692755] Enqueued task 'Deploy TFTP PXEGrub config for chd-dev-vptest01.companydomain.com' to 'Host::Managed Main' queue
2021-11-22T07:26:01 [D|app|53692755] Enqueued task 'Deploy TFTP iPXE config for chd-dev-vptest01.companydomain.com' to 'Host::Managed Main' queue
2021-11-22T07:26:01 [D|app|53692755] Enqueued task 'refresh_content_host_status_1062' to 'Host::Managed Main' queue
2021-11-22T07:26:01 [D|app|53692755] Processing task 'Deploy TFTP PXELinux config for chd-dev-vptest01.companydomain.com' from 'Host::Managed Main'
2021-11-22T07:26:01 [I|app|53692755] Deploying TFTP PXELinux configuration for chd-dev-vptest01.companydomain.com
2021-11-22T07:26:01 [D|app|53692755] Processing task 'Deploy TFTP PXEGrub2 config for chd-dev-vptest01.companydomain.com' from 'Host::Managed Main'
2021-11-22T07:26:01 [I|app|53692755] Deploying TFTP PXEGrub2 configuration for chd-dev-vptest01.companydomain.com
2021-11-22T07:26:01 [D|app|53692755] Processing task 'Deploy TFTP PXEGrub config for chd-dev-vptest01.companydomain.com' from 'Host::Managed Main'
2021-11-22T07:26:01 [I|app|53692755] Deploying TFTP PXEGrub configuration for chd-dev-vptest01.companydomain.com
2021-11-22T07:26:01 [D|app|53692755] Processing task 'Deploy TFTP iPXE config for chd-dev-vptest01.companydomain.com' from 'Host::Managed Main'
2021-11-22T07:26:03 [I|app|53692755] Deploying TFTP iPXE configuration for chd-dev-vptest01.companydomain.com
2021-11-22T07:26:03 [D|app|53692755] Processing task 'Refresh Content Host Statuses for chd-dev-vptest01.companydomain.com' from 'Host::Managed Main'
2021-11-22T07:26:03 [I|aud|53692755] Host::Base (1062) update event on build true, false
2021-11-22T07:26:03 [I|aud|53692755] Host::Base (1062) update event on installed_at , 2021-11-22 13:26:01 UTC
2021-11-22T07:26:03 [I|aud|53692755] Host::Base (1062) update event on grub_pass $6$wYGWGAMnH9DWf8N3$MWaUoQMQ9BPO1ojP0GwL6CeOjRMsS9fFXelWJb8OZEOUinuhWDWr75eFr8t8NmhBfwym4HYvFbKO3MS/dasl51, $5$BLWbVilfinp71Uta$MpMAPuua0mBFi0AOysICBD0Jx9qRFm16Gu65hAuuU04
2021-11-22T07:26:03 [I|app|53692755] Processed 5 tasks from queue 'Host::Managed Main', completed 5/5
2021-11-22T07:26:03 [D|app|53692755] Task 'Deploy TFTP PXELinux config for chd-dev-vptest01.companydomain.com' *completed*
2021-11-22T07:26:03 [D|app|53692755] Task 'Deploy TFTP PXEGrub2 config for chd-dev-vptest01.companydomain.com' *completed*
2021-11-22T07:26:03 [D|app|53692755] Task 'Deploy TFTP PXEGrub config for chd-dev-vptest01.companydomain.com' *completed*
2021-11-22T07:26:03 [D|app|53692755] Task 'Deploy TFTP iPXE config for chd-dev-vptest01.companydomain.com' *completed*
2021-11-22T07:26:03 [D|app|53692755] Task 'Refresh Content Host Statuses for chd-dev-vptest01.companydomain.com' *completed*
2021-11-22T07:26:03 [D|not|53692755] Notification event: Hosts::BuildCompleted - checking for notifications
2021-11-22T07:26:03 [D|not|53692755] Clearing Cache: notification, clearing cache for notification-14
2021-11-22T07:26:03 [I|app|53692755] Completed 201 Created in 1844ms (ActiveRecord: 32.8ms | Allocations: 125317)
2021-11-22T07:26:06 [D|dyn|] Executor heartbeat
2021-11-22T07:26:10 [I|app|de5f37cf] Started GET "/notification_recipients" for 10.48.69.31 at 2021-11-22 07:26:10 -0600
2021-11-22T07:26:10 [I|app|de5f37cf] Processing by NotificationRecipientsController#index as JSON
2021-11-22T07:26:10 [D|tax|de5f37cf] Current location set to none
2021-11-22T07:26:10 [D|tax|de5f37cf] Current organization set to none
2021-11-22T07:26:10 [D|not|de5f37cf] Cache Miss: notification, writing cache for notification-14
2021-11-22T07:26:10 [D|not|de5f37cf] Expiring notification cache notification-14 in 85478.131270346 seconds
2021-11-22T07:26:10 [D|app|de5f37cf] Body: {"notifications":[{"id":146417,"seen":false,"level":"success","text":"chd-dev-vptest01.companydomain.com has been provisioned successfully","created_at":"2021-11-22T13:26:03.278Z","group":"Hosts","actions":{"links":[{"href":"/hosts/chd-dev-vptest01.companydomain.com","title":"Details"}]}},{"id":146394,"seen":false,"level":"info","text":"chd-dev-vptest01.companydomain.com has been deleted successfully","created_at":"2021-11-22T13:10:49.021Z","group":"Hosts","actions":{}},{"id":146381,"seen":false,"level":"error","text":"One or more hosts with failed discovery due to error: undefined method `reports' for #\u003cHost::Discovered:0x000000001fe1b990\u003e","created_at":"2021-11-22T09:00:06.235Z","group":"Hosts","actions":{}}]}

ShoeFace · November 23, 2021, 2:43am

I can say I’m experiencing the same behavior on Foreman 2.5

obol89 · December 3, 2021, 3:23pm

@aruzicka Do you have any thoughts?

obol89 · December 21, 2021, 1:34pm

Hi,
Were you able to solve this problem?

ShoeFace · December 30, 2021, 9:50pm

No. Just been pressing the run Ansible roles button after building for the time being

aruzicka · January 3, 2022, 8:39am

This should get fixed once Fixes #34110 - Delay host global status update by ofedoren · Pull Request #9842 · Katello/katello · GitHub gets into a release.