Ansible roles are not starting automatically after provisioning

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

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

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

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

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":{}}]}

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