Foreman domains DNS proxy slow

mike1260 · February 25, 2021, 10:17am

Problem:
Hello Foreman team!

I’m experiencing a very strange behaviour when using dns feature in the foreman web gui.

When I set the DNS proxy for any of my managed domains in Infrastructure > Domains Then I create or edit a host that is in that domain, it takes about 80 seconds (2 minutes and 20 seconds) to return to the host list page. No error appears in the log nor in the web gui and the host is successfully created in my dns server.

However, when I unset the DNS proxy in that domain (mydomain.com) the host creation or edits are saved almost instantly.

Interestingly enough, when dns proxy is unset from the domain, but the subnet has the dns proxy set the for reverse dns, the host creation or edits are saved almost instantly also.

Note that I’m using powerdns, but the problem happen with bind or with dns_dnsupdate as well. So my guess is that foreman-proxy isn’t the cause as the function is working as expected for reverse dns.

Also, when the dns proxy is set in (mydomain.com) while editing one of my host that has that domain name configured for, while watching the logs, it seems to be stuck in a loop because the following happen multiple time:

2021-02-25T10:29:45 [I|app|a766a627] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:29:45 +0100
2021-02-25T10:29:45 [I|app|a766a627] Processing by TasksController#show as */*
2021-02-25T10:29:45 [I|app|a766a627]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:29:45 [I|app|a766a627]   Rendered tasks/_list.html.erb (Duration: 0.7ms | Allocations: 251)
2021-02-25T10:29:45 [I|app|a766a627] Completed 200 OK in 9ms (Views: 2.2ms | ActiveRecord: 1.2ms | Allocations: 2561)

I also check for the cpu load or memory, nothing relevant here.

Again, the problem only happen when the dns proxy is set on domains. When unset, everything fine. But that not what I’m after as I’d like to use foreman for all our orchestration process. DNS, DHCP, TFTP, etc.

I hope you can help me out.

If i forgot something, please tell me.

Expected outcome:

It should create or save my host in less than 80 seconds (2 minutes and 20 seconds).

Foreman and Proxy versions:

Foreman version foreman-2.4.0-0.2.rc2

foreman-proxy-2.4.0-0.1.rc2

Foreman and Proxy plugin versions:

foreman-postgresql-2.4.0-0.4.rc2.el8.noarch
rubygem-hammer_cli_foreman_discovery-1.0.2-1.fm2_1.el8.noarch
rubygem-foreman_discovery-16.3.4-2.fm2_4.el8.noarch
rubygem-foreman_remote_execution-cockpit-4.2.2-1.fm2_4.el8.noarch
foreman-debug-2.4.0-0.4.rc2.el8.noarch
foreman-proxy-2.4.0-0.1.rc2.el8.noarch
rubygem-foreman-tasks-core-0.3.4-1.fm2_1.el8.noarch
rubygem-foreman_ansible-6.1.1-1.fm2_4.el8.noarch
rubygem-foreman_hooks-0.3.17-1.fm2_4.el8.noarch
rubygem-foreman_remote_execution-4.2.2-1.fm2_4.el8.noarch
rubygem-foreman_templates-9.0.1-1.fm2_2.el8.noarch
rubygem-foreman_ansible_core-4.0.0-1.fm2_4.el8.noarch
rubygem-hammer_cli_foreman-2.4.0-1.el8.noarch
foreman-vmware-2.4.0-0.4.rc2.el8.noarch
rubygem-hammer_cli_foreman_templates-0.2.0-1.fm2_1.el8.noarch
rubygem-foreman_remote_execution_core-1.4.0-1.el8.noarch
foreman-cli-2.4.0-0.4.rc2.el8.noarch
foreman-service-2.4.0-0.4.rc2.el8.noarch
foreman-release-2.4.0-0.2.rc2.el8.noarch
foreman-2.4.0-0.4.rc2.el8.noarch
foreman-installer-2.4.0-0.1.rc2.el8.noarch
rubygem-foreman-tasks-3.0.3-1.fm2_4.el8.noarch
foreman-dynflow-sidekiq-2.4.0-0.4.rc2.el8.noarch
rubygem-hammer_cli_foreman_ansible-0.3.3-1.fm2_4.el8.noarch
rubygem-foreman_bootdisk-17.0.2-2.fm2_2.el8.noarch
rubygem-foreman_kubevirt-0.1.9-1.fm2_4.el8.noarch

Distribution and version:

CentOS Linux release 8.3.2011

Other relevant data:

Foreman was installed using foreman-installer with the following parameters

foreman-installer \
        --enable-foreman-proxy \
        --foreman-proxy-tftp=true \
        --foreman-proxy-tftp-servername=tfm-01.mydomain.lab \
        --foreman-proxy-dns=false \
        --foreman-proxy-dns-interface=ens160 \
        --foreman-proxy-dns-zone=mydomain.lab \
        --enable-foreman-plugin-remote-execution \
        --enable-foreman-proxy-plugin-remote-execution-ssh \
        --enable-foreman-plugin-ansible \
        --enable-foreman-proxy-plugin-ansible \
        --enable-foreman-plugin-discovery \
        --enable-foreman-cli-discovery \
        --enable-foreman-cli-ansible \
        --enable-foreman-cli-templates \
        --enable-foreman-plugin-templates \
        --enable-foreman-plugin-bootdisk \
        --foreman-proxy-bmc true \
        --enable-foreman-compute-vmware \
        --foreman-proxy-dhcp=false \
        --foreman-proxy-dhcp-managed=false \
        --foreman-proxy-dhcp-range=false \
        --foreman-proxy-dhcp-option-domain=false \
        --enable-foreman-plugin-kubevirt \
        --enable-foreman-plugin-remote-execution-cockpit \
        --foreman-proxy-httpboot true \
        --enable-foreman-plugin-hooks \
        --foreman-proxy-dns true \
        --enable-foreman-proxy-plugin-dns-powerdns \
        --foreman-proxy-plugin-dns-powerdns-rest-api-key="my-api-key" \
        --foreman-proxy-plugin-dns-powerdns-rest-url="http://172.22.63.17:8081/api/v1/servers/localhost"

The server is running on a ESXi 7 hypervisor
VM configuration:
8Gb of ram
4 vCPU
200Gb of storage disk

Foreman and Foreman-proxy are running on the same host. However, the dns server is hosted on another vm and does not have foreman-proxy installed.

Foreman and forman-proxy IP: 172.22.63.5
DNS Server IP: 172.22.63.17

All log_level for foreman and foreman-proxy has been turned to DEBUG

/var/log/foreman/production.log

2021-02-25T10:29:43 [I|app|a58a08b8] Started PATCH "/hosts/10" for 127.0.0.1 at 2021-02-25 10:29:43 +0100
2021-02-25T10:29:43 [I|app|a58a08b8] Processing by HostsController#update as */*
2021-02-25T10:29:43 [I|app|a58a08b8]   Parameters: {"utf8"=>"✓", "authenticity_token"=>"[FILTERED]", "host"=>{"name"=>"test-host", "hostgroup_id"=>"1", "environment_id"=>"1", "puppet_proxy_id"=>"1", "puppet_ca_proxy_id"=>"1", "ansible_role_ids"=>[""], "puppetclass_ids"=>[""], "managed"=>"true", "progress_report_id"=>"[FILTERED]", "interfaces_attributes"=>{"0"=>{"_destroy"=>"0", "mac"=>"00:0c:29:20:c8:5e", "identifier"=>"ens160", "name"=>"test-host", "domain_id"=>"2", "subnet_id"=>"1", "ip"=>"172.22.63.170", "ip6"=>"", "managed"=>"1", "primary"=>"1", "provision"=>"1", "execution"=>"1", "tag"=>"", "attached_to"=>"", "id"=>"18"}}, "architecture_id"=>"1", "operatingsystem_id"=>"3", "medium_id"=>"14", "ptable_id"=>"166", "pxe_loader"=>"Grub2 UEFI", "disk"=>"", "is_owned_by"=>"4-Users", "enabled"=>"1", "model_id"=>"", "comment"=>"", "overwrite"=>"false"}, "id"=>"10"}
2021-02-25T10:29:43 [D|tax|a58a08b8] Current location set to Default Location
2021-02-25T10:29:43 [D|tax|a58a08b8] Current organization set to Default Organization
2021-02-25T10:29:43 [D|tax|a58a08b8] Current organization set to none
2021-02-25T10:29:43 [D|tax|a58a08b8] Current location set to none
2021-02-25T10:29:44 [I|app|0d1b4ec5] Started GET "/notification_recipients" for 127.0.0.1 at 2021-02-25 10:29:44 +0100
2021-02-25T10:29:44 [I|app|0d1b4ec5] Processing by NotificationRecipientsController#index as JSON
2021-02-25T10:29:44 [D|tax|0d1b4ec5] Current location set to Default Location
2021-02-25T10:29:44 [D|tax|0d1b4ec5] Current organization set to Default Organization
2021-02-25T10:29:44 [D|not|0d1b4ec5] Cache Hit: notification, reading cache for notification-4
2021-02-25T10:29:44 [D|app|0d1b4ec5] Body: {"notifications":[]}
2021-02-25T10:29:44 [I|app|0d1b4ec5] Completed 200 OK in 10ms (Views: 0.2ms | ActiveRecord: 1.4ms | Allocations: 2495)
2021-02-25T10:29:45 [I|app|a766a627] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:29:45 +0100
2021-02-25T10:29:45 [I|app|a766a627] Processing by TasksController#show as */*
2021-02-25T10:29:45 [I|app|a766a627]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:29:45 [I|app|a766a627]   Rendered tasks/_list.html.erb (Duration: 0.7ms | Allocations: 251)
2021-02-25T10:29:45 [I|app|a766a627] Completed 200 OK in 9ms (Views: 2.2ms | ActiveRecord: 1.2ms | Allocations: 2561)
2021-02-25T10:29:46 [I|app|53cc386b] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:29:46 +0100
2021-02-25T10:29:46 [I|app|53cc386b] Processing by TasksController#show as */*
2021-02-25T10:29:46 [I|app|53cc386b]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:29:46 [I|app|53cc386b]   Rendered tasks/_list.html.erb (Duration: 5.8ms | Allocations: 5662)
2021-02-25T10:29:46 [I|app|53cc386b] Completed 200 OK in 13ms (Views: 6.3ms | ActiveRecord: 1.3ms | Allocations: 7269)
2021-02-25T10:29:48 [I|app|a8647bdb] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:29:48 +0100
2021-02-25T10:29:48 [I|app|a8647bdb] Processing by TasksController#show as */*
2021-02-25T10:29:48 [I|app|a8647bdb]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:29:48 [I|app|a8647bdb]   Rendered tasks/_list.html.erb (Duration: 13.3ms | Allocations: 5662)
2021-02-25T10:29:48 [I|app|a8647bdb] Completed 200 OK in 21ms (Views: 13.8ms | ActiveRecord: 0.9ms | Allocations: 7268)
2021-02-25T10:29:50 [I|app|ca276376] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:29:50 +0100
2021-02-25T10:29:50 [I|app|ca276376] Processing by TasksController#show as */*
2021-02-25T10:29:50 [I|app|ca276376]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:29:50 [I|app|ca276376]   Rendered tasks/_list.html.erb (Duration: 9.9ms | Allocations: 5662)
2021-02-25T10:29:50 [I|app|ca276376] Completed 200 OK in 18ms (Views: 10.4ms | ActiveRecord: 0.9ms | Allocations: 7268)
2021-02-25T10:29:51 [I|app|de65cb97] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:29:51 +0100
2021-02-25T10:29:51 [I|app|de65cb97] Processing by TasksController#show as */*
2021-02-25T10:29:51 [I|app|de65cb97]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:29:51 [I|app|de65cb97]   Rendered tasks/_list.html.erb (Duration: 10.8ms | Allocations: 5662)
2021-02-25T10:29:51 [I|app|de65cb97] Completed 200 OK in 20ms (Views: 12.1ms | ActiveRecord: 0.8ms | Allocations: 7268)
2021-02-25T10:29:53 [I|app|f87f541c] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:29:53 +0100
2021-02-25T10:29:53 [I|app|f87f541c] Processing by TasksController#show as */*
2021-02-25T10:29:53 [I|app|f87f541c]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:29:53 [I|app|f87f541c]   Rendered tasks/_list.html.erb (Duration: 11.1ms | Allocations: 5662)
2021-02-25T10:29:53 [I|app|f87f541c] Completed 200 OK in 19ms (Views: 11.4ms | ActiveRecord: 0.8ms | Allocations: 7268)
2021-02-25T10:29:54 [I|app|12c131ca] Started GET "/notification_recipients" for 127.0.0.1 at 2021-02-25 10:29:54 +0100
2021-02-25T10:29:54 [I|app|12c131ca] Processing by NotificationRecipientsController#index as JSON
2021-02-25T10:29:54 [D|tax|12c131ca] Current location set to Default Location
2021-02-25T10:29:54 [D|tax|12c131ca] Current organization set to Default Organization
2021-02-25T10:29:54 [D|not|12c131ca] Cache Hit: notification, reading cache for notification-4
2021-02-25T10:29:54 [D|app|12c131ca] Body: {"notifications":[]}
2021-02-25T10:29:54 [I|app|12c131ca] Completed 200 OK in 11ms (Views: 0.1ms | ActiveRecord: 1.0ms | Allocations: 2240)
2021-02-25T10:29:55 [I|app|ed1f27e6] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:29:55 +0100
2021-02-25T10:29:55 [I|app|ed1f27e6] Processing by TasksController#show as */*
2021-02-25T10:29:55 [I|app|ed1f27e6]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:29:55 [I|app|ed1f27e6]   Rendered tasks/_list.html.erb (Duration: 11.8ms | Allocations: 5662)
2021-02-25T10:29:55 [I|app|ed1f27e6] Completed 200 OK in 19ms (Views: 12.2ms | ActiveRecord: 0.8ms | Allocations: 7268)
2021-02-25T10:29:56 [I|app|93ebe219] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:29:56 +0100
2021-02-25T10:29:56 [I|app|93ebe219] Processing by TasksController#show as */*
2021-02-25T10:29:56 [I|app|93ebe219]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:29:56 [I|app|93ebe219]   Rendered tasks/_list.html.erb (Duration: 10.8ms | Allocations: 5662)
2021-02-25T10:29:56 [I|app|93ebe219] Completed 200 OK in 19ms (Views: 11.2ms | ActiveRecord: 0.9ms | Allocations: 7268)
2021-02-25T10:29:58 [I|app|f78b60cd] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:29:58 +0100
2021-02-25T10:29:58 [I|app|f78b60cd] Processing by TasksController#show as */*
2021-02-25T10:29:58 [I|app|f78b60cd]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:29:58 [I|app|f78b60cd]   Rendered tasks/_list.html.erb (Duration: 11.8ms | Allocations: 5662)
2021-02-25T10:29:58 [I|app|f78b60cd] Completed 200 OK in 21ms (Views: 13.0ms | ActiveRecord: 0.7ms | Allocations: 7268)
2021-02-25T10:30:00 [I|app|dfd3ad34] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:30:00 +0100
2021-02-25T10:30:00 [I|app|dfd3ad34] Processing by TasksController#show as */*
2021-02-25T10:30:00 [I|app|dfd3ad34]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:30:00 [I|app|dfd3ad34]   Rendered tasks/_list.html.erb (Duration: 10.9ms | Allocations: 5662)
2021-02-25T10:30:00 [I|app|dfd3ad34] Completed 200 OK in 19ms (Views: 12.1ms | ActiveRecord: 0.8ms | Allocations: 7268)
2021-02-25T10:30:01 [I|app|0650ee4b] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:30:01 +0100
2021-02-25T10:30:02 [I|app|0650ee4b] Processing by TasksController#show as */*
2021-02-25T10:30:02 [I|app|0650ee4b]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:30:02 [I|app|0650ee4b]   Rendered tasks/_list.html.erb (Duration: 8.4ms | Allocations: 5662)
2021-02-25T10:30:02 [I|app|0650ee4b] Completed 200 OK in 16ms (Views: 9.3ms | ActiveRecord: 0.7ms | Allocations: 7268)
2021-02-25T10:30:03 [I|app|] Rails cache backend: File
2021-02-25T10:30:03 [I|app|5eabb0a3] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:30:03 +0100
2021-02-25T10:30:03 [I|app|5eabb0a3] Processing by TasksController#show as */*
2021-02-25T10:30:03 [I|app|5eabb0a3]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:30:03 [I|app|5eabb0a3]   Rendered tasks/_list.html.erb (Duration: 8.4ms | Allocations: 5663)
2021-02-25T10:30:03 [I|app|5eabb0a3] Completed 200 OK in 15ms (Views: 8.8ms | ActiveRecord: 0.8ms | Allocations: 7280)
2021-02-25T10:30:04 [I|app|be00edda] Started GET "/notification_recipients" for 127.0.0.1 at 2021-02-25 10:30:04 +0100
2021-02-25T10:30:04 [I|app|be00edda] Processing by NotificationRecipientsController#index as JSON
2021-02-25T10:30:04 [D|tax|be00edda] Current location set to Default Location
2021-02-25T10:30:04 [D|tax|be00edda] Current organization set to Default Organization
2021-02-25T10:30:04 [D|not|be00edda] Cache Hit: notification, reading cache for notification-4
2021-02-25T10:30:04 [D|app|be00edda] Body: {"notifications":[]}
2021-02-25T10:30:04 [I|app|be00edda] Completed 200 OK in 6ms (Views: 0.1ms | ActiveRecord: 0.8ms | Allocations: 2240)
2021-02-25T10:30:05 [D|app|] Registering 4 assets for plugin foreman-tasks precompilation
2021-02-25T10:30:05 [D|app|] Registering 6 assets for plugin foreman_remote_execution precompilation
2021-02-25T10:30:05 [D|app|] Registering 2 assets for plugin foreman_ansible precompilation
2021-02-25T10:30:05 [D|app|] Registering 1 assets for plugin foreman_bootdisk precompilation
2021-02-25T10:30:05 [D|app|] Plugin foreman_kubevirt has assets outside of its namespace, these will be ignored: bundle.js
2021-02-25T10:30:05 [D|app|] Registering 2 assets for plugin foreman_kubevirt precompilation
2021-02-25T10:30:05 [I|app|bddd1027] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:30:05 +0100
2021-02-25T10:30:05 [I|app|bddd1027] Processing by TasksController#show as */*
2021-02-25T10:30:05 [I|app|bddd1027]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:30:05 [I|app|bddd1027]   Rendered tasks/_list.html.erb (Duration: 6.9ms | Allocations: 5662)
2021-02-25T10:30:05 [I|app|bddd1027] Completed 200 OK in 14ms (Views: 7.7ms | ActiveRecord: 0.8ms | Allocations: 7268)
2021-02-25T10:30:05 [W|app|] Creating scope :completer_scope. Overwriting existing method Location.completer_scope.
2021-02-25T10:30:05 [W|app|] Creating scope :completer_scope. Overwriting existing method Organization.completer_scope.
2021-02-25T10:30:05 [D|app|] Loading foreman-tasks precompiled asset manifest from /usr/share/gems/gems/foreman-tasks-3.0.3/public/assets/foreman-tasks/foreman-tasks.json
2021-02-25T10:30:05 [D|app|] Loading foreman_ansible precompiled asset manifest from /usr/share/gems/gems/foreman_ansible-6.1.1/public/assets/foreman_ansible/foreman_ansible.json
2021-02-25T10:30:05 [D|app|] Loading foreman_bootdisk precompiled asset manifest from /usr/share/gems/gems/foreman_bootdisk-17.0.2/public/assets/foreman_bootdisk/foreman_bootdisk.json
2021-02-25T10:30:05 [D|app|] Loading foreman_discovery precompiled asset manifest from /usr/share/gems/gems/foreman_discovery-16.3.4/public/assets/foreman_discovery/foreman_discovery.json
2021-02-25T10:30:05 [D|app|] Loading foreman_kubevirt precompiled asset manifest from /usr/share/gems/gems/foreman_kubevirt-0.1.9/public/assets/foreman_kubevirt/foreman_kubevirt.json
2021-02-25T10:30:05 [D|app|] Loading foreman_remote_execution precompiled asset manifest from /usr/share/gems/gems/foreman_remote_execution-4.2.2/public/assets/foreman_remote_execution/foreman_remote_execution.json
2021-02-25T10:30:05 [D|app|] Loading foreman_templates precompiled asset manifest from /usr/share/gems/gems/foreman_templates-9.0.1/public/assets/foreman_templates/foreman_templates.json
2021-02-25T10:30:06 [D|app|] Loading foreman-tasks webpack asset manifest from /usr/share/gems/gems/foreman-tasks-3.0.3/public/webpack/foreman-tasks/manifest.json
2021-02-25T10:30:06 [D|app|] Loading foreman_ansible webpack asset manifest from /usr/share/gems/gems/foreman_ansible-6.1.1/public/webpack/foreman_ansible/manifest.json
2021-02-25T10:30:06 [D|app|] Loading foreman_discovery webpack asset manifest from /usr/share/gems/gems/foreman_discovery-16.3.4/public/webpack/foreman_discovery/manifest.json
2021-02-25T10:30:06 [D|app|] Loading foreman_remote_execution webpack asset manifest from /usr/share/gems/gems/foreman_remote_execution-4.2.2/public/webpack/foreman_remote_execution/manifest.json
2021-02-25T10:30:06 [D|app|] Loading foreman_templates webpack asset manifest from /usr/share/gems/gems/foreman_templates-9.0.1/public/webpack/foreman_templates/manifest.json
2021-02-25T10:30:07 [I|app|c9e15c41] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:30:07 +0100
2021-02-25T10:30:07 [I|app|c9e15c41] Processing by TasksController#show as */*
2021-02-25T10:30:07 [I|app|c9e15c41]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:30:07 [I|app|c9e15c41]   Rendered tasks/_list.html.erb (Duration: 6.2ms | Allocations: 5662)
2021-02-25T10:30:07 [I|app|c9e15c41] Completed 200 OK in 12ms (Views: 6.6ms | ActiveRecord: 0.8ms | Allocations: 7268)
2021-02-25T10:30:08 [I|bac|d280057b] Task {label: Actions::RemoteExecution::RunHostsJob, id: 3e59b5e9-f3d2-41a3-8c75-60161a2ddcae, execution_plan_id: 86ac94f0-e8d2-43ff-a922-cfdfcf9e60d5} state changed: planning 
2021-02-25T10:30:08 [I|app|76fefef8] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:30:08 +0100
2021-02-25T10:30:08 [I|app|76fefef8] Processing by TasksController#show as */*
2021-02-25T10:30:08 [I|app|76fefef8]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:30:08 [I|app|76fefef8]   Rendered tasks/_list.html.erb (Duration: 7.4ms | Allocations: 5662)
2021-02-25T10:30:08 [I|app|76fefef8] Completed 200 OK in 13ms (Views: 8.3ms | ActiveRecord: 0.7ms | Allocations: 7268)
2021-02-25T10:30:08 [I|bac|d280057b] Task {label: Actions::RemoteExecution::RunHostsJob, id: 3e59b5e9-f3d2-41a3-8c75-60161a2ddcae, execution_plan_id: 86ac94f0-e8d2-43ff-a922-cfdfcf9e60d5} state changed: planned 
2021-02-25T10:30:08 [I|aud|784dd824] JobInvocation (131) create event on job_category Ansible Commands
2021-02-25T10:30:08 [I|aud|784dd824] JobInvocation (131) create event on description Gathering facts
2021-02-25T10:30:08 [I|aud|784dd824] JobInvocation (131) create event on concurrency_level 
2021-02-25T10:30:08 [I|aud|784dd824] JobInvocation (131) create event on time_span 
2021-02-25T10:30:08 [I|aud|784dd824] JobInvocation (131) create event on execution_timeout_interval 
2021-02-25T10:30:08 [I|aud|784dd824] JobInvocation (131) create event on password [redacted]
2021-02-25T10:30:08 [I|aud|784dd824] JobInvocation (131) create event on key_passphrase 
2021-02-25T10:30:08 [I|aud|784dd824] JobInvocation (131) create event on remote_execution_feature_id 
2021-02-25T10:30:08 [I|aud|784dd824] JobInvocation (131) create event on effective_user_password 
2021-02-25T10:30:08 [I|bac|784dd824] Task {label: Actions::RemoteExecution::RunHostsJob, id: 371377a5-3441-4ccb-b455-b8ba3b380b2b, execution_plan_id: 22342e88-388e-419a-b042-47bbdb3981d6} state changed: scheduled 
2021-02-25T10:30:08 [I|bac|d280057b] Task {label: Actions::RemoteExecution::RunHostsJob, id: 3e59b5e9-f3d2-41a3-8c75-60161a2ddcae, execution_plan_id: 86ac94f0-e8d2-43ff-a922-cfdfcf9e60d5} state changed: running 
2021-02-25T10:30:09 [W|app|d280057b] Scoped order is ignored, it's forced to be batch order.
2021-02-25T10:30:09 [W|app|d280057b] Scoped order is ignored, it's forced to be batch order.
2021-02-25T10:30:10 [I|app|40deb23c] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:30:10 +0100
2021-02-25T10:30:10 [I|app|40deb23c] Processing by TasksController#show as */*
2021-02-25T10:30:10 [I|app|40deb23c]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:30:10 [I|app|40deb23c]   Rendered tasks/_list.html.erb (Duration: 8.5ms | Allocations: 5662)
2021-02-25T10:30:10 [I|app|40deb23c] Completed 200 OK in 15ms (Views: 8.9ms | ActiveRecord: 0.8ms | Allocations: 7268)
2021-02-25T10:30:12 [I|app|5220df1c] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:30:12 +0100
2021-02-25T10:30:12 [I|app|5220df1c] Processing by TasksController#show as */*
2021-02-25T10:30:12 [I|app|5220df1c]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:30:12 [I|app|5220df1c]   Rendered tasks/_list.html.erb (Duration: 9.4ms | Allocations: 5662)
2021-02-25T10:30:12 [I|app|5220df1c] Completed 200 OK in 18ms (Views: 10.5ms | ActiveRecord: 1.0ms | Allocations: 7268)
2021-02-25T10:30:13 [I|app|871fd051] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:30:13 +0100
2021-02-25T10:30:13 [I|app|871fd051] Processing by TasksController#show as */*
2021-02-25T10:30:13 [I|app|871fd051]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:30:13 [I|app|871fd051]   Rendered tasks/_list.html.erb (Duration: 9.8ms | Allocations: 5662)
2021-02-25T10:30:13 [I|app|871fd051] Completed 200 OK in 17ms (Views: 10.2ms | ActiveRecord: 0.9ms | Allocations: 7268)
2021-02-25T10:30:14 [I|app|3aac1630] Started GET "/notification_recipients" for 127.0.0.1 at 2021-02-25 10:30:14 +0100
2021-02-25T10:30:14 [I|app|3aac1630] Processing by NotificationRecipientsController#index as JSON
2021-02-25T10:30:14 [D|tax|3aac1630] Current location set to Default Location
2021-02-25T10:30:14 [D|tax|3aac1630] Current organization set to Default Organization
2021-02-25T10:30:14 [D|not|3aac1630] Cache Hit: notification, reading cache for notification-4
2021-02-25T10:30:14 [D|app|3aac1630] Body: {"notifications":[]}
2021-02-25T10:30:14 [I|app|3aac1630] Completed 200 OK in 9ms (Views: 0.1ms | ActiveRecord: 0.9ms | Allocations: 2240)
2021-02-25T10:30:15 [I|app|03263fff] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:30:15 +0100
2021-02-25T10:30:15 [I|app|03263fff] Processing by TasksController#show as */*
2021-02-25T10:30:15 [I|app|03263fff]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:30:15 [I|app|03263fff]   Rendered tasks/_list.html.erb (Duration: 5.0ms | Allocations: 5662)
2021-02-25T10:30:15 [I|app|03263fff] Completed 200 OK in 11ms (Views: 5.4ms | ActiveRecord: 0.8ms | Allocations: 7268)
2021-02-25T10:30:17 [I|app|8a5aa43a] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:30:17 +0100
2021-02-25T10:30:17 [I|app|8a5aa43a] Processing by TasksController#show as */*
2021-02-25T10:30:17 [I|app|8a5aa43a]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:30:17 [I|app|8a5aa43a]   Rendered tasks/_list.html.erb (Duration: 3.5ms | Allocations: 5662)
2021-02-25T10:30:17 [I|app|8a5aa43a] Completed 200 OK in 10ms (Views: 3.8ms | ActiveRecord: 0.9ms | Allocations: 7268)
2021-02-25T10:30:18 [I|app|561b3477] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:30:18 +0100
2021-02-25T10:30:18 [I|app|561b3477] Processing by TasksController#show as */*
2021-02-25T10:30:18 [I|app|561b3477]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:30:18 [I|app|561b3477]   Rendered tasks/_list.html.erb (Duration: 4.1ms | Allocations: 5662)
2021-02-25T10:30:18 [I|app|561b3477] Completed 200 OK in 10ms (Views: 4.5ms | ActiveRecord: 0.9ms | Allocations: 7268)
2021-02-25T10:30:19 [I|bac|d280057b] Task {label: Actions::RemoteExecution::RunHostsJob, id: 3e59b5e9-f3d2-41a3-8c75-60161a2ddcae, execution_plan_id: 86ac94f0-e8d2-43ff-a922-cfdfcf9e60d5} state changed: stopped  result: success
2021-02-25T10:30:19 [I|bac|d280057b] Task {label: Actions::RemoteExecution::RunHostsJob, id: 3e59b5e9-f3d2-41a3-8c75-60161a2ddcae, execution_plan_id: 86ac94f0-e8d2-43ff-a922-cfdfcf9e60d5} state changed: stopped  result: success
2021-02-25T10:30:20 [I|app|22b076e1] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:30:20 +0100
2021-02-25T10:30:20 [I|app|22b076e1] Processing by TasksController#show as */*
2021-02-25T10:30:20 [I|app|22b076e1]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:30:20 [I|app|22b076e1]   Rendered tasks/_list.html.erb (Duration: 3.6ms | Allocations: 5662)
2021-02-25T10:30:20 [I|app|22b076e1] Completed 200 OK in 9ms (Views: 4.0ms | ActiveRecord: 0.8ms | Allocations: 7268)
2021-02-25T10:30:22 [I|app|fda0c640] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:30:22 +0100
2021-02-25T10:30:22 [I|app|fda0c640] Processing by TasksController#show as */*
2021-02-25T10:30:22 [I|app|fda0c640]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:30:22 [I|app|fda0c640]   Rendered tasks/_list.html.erb (Duration: 4.1ms | Allocations: 5662)
2021-02-25T10:30:22 [I|app|fda0c640] Completed 200 OK in 10ms (Views: 4.5ms | ActiveRecord: 0.8ms | Allocations: 7268)
2021-02-25T10:30:23 [I|app|d705ba8e] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:30:23 +0100
2021-02-25T10:30:23 [I|app|d705ba8e] Processing by TasksController#show as */*
2021-02-25T10:30:23 [I|app|d705ba8e]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:30:23 [I|app|d705ba8e]   Rendered tasks/_list.html.erb (Duration: 5.2ms | Allocations: 5662)
2021-02-25T10:30:23 [I|app|d705ba8e] Completed 200 OK in 14ms (Views: 5.8ms | ActiveRecord: 1.1ms | Allocations: 7268)
2021-02-25T10:30:24 [I|app|332503ab] Started GET "/notification_recipients" for 127.0.0.1 at 2021-02-25 10:30:24 +0100
2021-02-25T10:30:24 [I|app|332503ab] Processing by NotificationRecipientsController#index as JSON
2021-02-25T10:30:24 [D|tax|332503ab] Current location set to Default Location
2021-02-25T10:30:24 [D|tax|332503ab] Current organization set to Default Organization
2021-02-25T10:30:24 [D|not|332503ab] Cache Miss: notification, writing cache for notification-4
2021-02-25T10:30:24 [D|not|332503ab] Expiring notification cache notification-4 in 86395.102719873 seconds
2021-02-25T10:30:24 [D|app|332503ab] Body: {"notifications":[{"id":132,"seen":false,"level":"success","text":"A job 'Gathering facts' has finished successfully","created_at":"2021-02-25T09:30:19.194Z","group":"Jobs","actions":{"links":[{"href":"/job_invocations/130","title":"Job Details"}]}}]}
2021-02-25T10:30:24 [I|app|332503ab] Completed 200 OK in 56ms (Views: 0.1ms | ActiveRecord: 18.2ms | Allocations: 23588)
2021-02-25T10:30:25 [I|app|c9a16e24] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:30:25 +0100
2021-02-25T10:30:25 [I|app|c9a16e24] Processing by TasksController#show as */*
2021-02-25T10:30:25 [I|app|c9a16e24]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:30:25 [I|app|c9a16e24]   Rendered tasks/_list.html.erb (Duration: 4.5ms | Allocations: 5663)
2021-02-25T10:30:25 [I|app|c9a16e24] Completed 200 OK in 11ms (Views: 4.9ms | ActiveRecord: 1.0ms | Allocations: 7269)
2021-02-25T10:30:27 [I|app|b0f7efef] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:30:27 +0100
2021-02-25T10:30:27 [I|app|b0f7efef] Processing by TasksController#show as */*
2021-02-25T10:30:27 [I|app|b0f7efef]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:30:27 [I|app|b0f7efef]   Rendered tasks/_list.html.erb (Duration: 4.4ms | Allocations: 5662)
2021-02-25T10:30:27 [I|app|b0f7efef] Completed 200 OK in 12ms (Views: 4.9ms | ActiveRecord: 1.1ms | Allocations: 7268)
2021-02-25T10:30:28 [I|app|e6fbfe7f] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:30:28 +0100
2021-02-25T10:30:28 [I|app|e6fbfe7f] Processing by TasksController#show as */*
2021-02-25T10:30:28 [I|app|e6fbfe7f]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:30:28 [I|app|e6fbfe7f]   Rendered tasks/_list.html.erb (Duration: 4.2ms | Allocations: 5662)
2021-02-25T10:30:28 [I|app|e6fbfe7f] Completed 200 OK in 12ms (Views: 4.6ms | ActiveRecord: 1.2ms | Allocations: 7268)
2021-02-25T10:30:30 [I|app|d14af2dc] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:30:30 +0100
2021-02-25T10:30:30 [I|app|d14af2dc] Processing by TasksController#show as */*
2021-02-25T10:30:30 [I|app|d14af2dc]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:30:30 [I|app|d14af2dc]   Rendered tasks/_list.html.erb (Duration: 4.1ms | Allocations: 5662)
2021-02-25T10:30:30 [I|app|d14af2dc] Completed 200 OK in 10ms (Views: 4.6ms | ActiveRecord: 0.9ms | Allocations: 7268)
2021-02-25T10:30:32 [I|app|50679ab2] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:30:32 +0100
2021-02-25T10:30:32 [I|app|50679ab2] Processing by TasksController#show as */*
2021-02-25T10:30:32 [I|app|50679ab2]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:30:32 [I|app|50679ab2]   Rendered tasks/_list.html.erb (Duration: 4.2ms | Allocations: 5662)
2021-02-25T10:30:32 [I|app|50679ab2] Completed 200 OK in 11ms (Views: 4.7ms | ActiveRecord: 0.9ms | Allocations: 7268)
2021-02-25T10:30:33 [I|app|fb1442af] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:30:33 +0100
2021-02-25T10:30:33 [I|app|fb1442af] Processing by TasksController#show as */*
2021-02-25T10:30:33 [I|app|fb1442af]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:30:33 [I|app|fb1442af]   Rendered tasks/_list.html.erb (Duration: 4.2ms | Allocations: 5663)
2021-02-25T10:30:33 [I|app|fb1442af] Completed 200 OK in 11ms (Views: 4.6ms | ActiveRecord: 1.0ms | Allocations: 7280)
2021-02-25T10:30:34 [I|app|55794ef3] Started GET "/notification_recipients" for 127.0.0.1 at 2021-02-25 10:30:34 +0100
2021-02-25T10:30:34 [I|app|55794ef3] Processing by NotificationRecipientsController#index as JSON
2021-02-25T10:30:34 [D|tax|55794ef3] Current location set to Default Location
2021-02-25T10:30:34 [D|tax|55794ef3] Current organization set to Default Organization
2021-02-25T10:30:34 [D|not|55794ef3] Cache Hit: notification, reading cache for notification-4
2021-02-25T10:30:34 [D|app|55794ef3] Body: {"notifications":[{"id":132,"seen":false,"level":"success","text":"A job 'Gathering facts' has finished successfully","created_at":"2021-02-25T09:30:19.194Z","group":"Jobs","actions":{"links":[{"href":"/job_invocations/130","title":"Job Details"}]}}]}
2021-02-25T10:30:34 [I|app|55794ef3] Completed 200 OK in 8ms (Views: 0.1ms | ActiveRecord: 1.2ms | Allocations: 2240)
2021-02-25T10:30:35 [I|app|864bf6a7] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:30:35 +0100
2021-02-25T10:30:35 [I|app|864bf6a7] Processing by TasksController#show as */*
2021-02-25T10:30:35 [I|app|864bf6a7]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:30:35 [I|app|864bf6a7]   Rendered tasks/_list.html.erb (Duration: 4.2ms | Allocations: 5662)
2021-02-25T10:30:35 [I|app|864bf6a7] Completed 200 OK in 11ms (Views: 4.7ms | ActiveRecord: 0.9ms | Allocations: 7268)
2021-02-25T10:30:37 [I|app|62e3923b] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:30:37 +0100
2021-02-25T10:30:37 [I|app|62e3923b] Processing by TasksController#show as */*
2021-02-25T10:30:37 [I|app|62e3923b]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:30:37 [I|app|62e3923b]   Rendered tasks/_list.html.erb (Duration: 4.5ms | Allocations: 5662)
2021-02-25T10:30:37 [I|app|62e3923b] Completed 200 OK in 11ms (Views: 5.0ms | ActiveRecord: 0.9ms | Allocations: 7268)
2021-02-25T10:30:38 [I|app|49c0004a] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:30:38 +0100
2021-02-25T10:30:38 [I|app|49c0004a] Processing by TasksController#show as */*
2021-02-25T10:30:38 [I|app|49c0004a]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:30:38 [I|app|49c0004a]   Rendered tasks/_list.html.erb (Duration: 4.6ms | Allocations: 5662)
2021-02-25T10:30:38 [I|app|49c0004a] Completed 200 OK in 11ms (Views: 5.0ms | ActiveRecord: 1.1ms | Allocations: 7268)
2021-02-25T10:30:40 [I|app|79702f49] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:30:40 +0100
2021-02-25T10:30:40 [I|app|79702f49] Processing by TasksController#show as */*
2021-02-25T10:30:40 [I|app|79702f49]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:30:40 [I|app|79702f49]   Rendered tasks/_list.html.erb (Duration: 4.8ms | Allocations: 5662)
2021-02-25T10:30:40 [I|app|79702f49] Completed 200 OK in 13ms (Views: 5.2ms | ActiveRecord: 1.1ms | Allocations: 7268)
2021-02-25T10:30:42 [I|app|074daef9] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:30:42 +0100
2021-02-25T10:30:42 [I|app|074daef9] Processing by TasksController#show as */*
2021-02-25T10:30:42 [I|app|074daef9]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:30:42 [I|app|074daef9]   Rendered tasks/_list.html.erb (Duration: 4.2ms | Allocations: 5662)
2021-02-25T10:30:42 [I|app|074daef9] Completed 200 OK in 12ms (Views: 4.7ms | ActiveRecord: 1.1ms | Allocations: 7268)
2021-02-25T10:30:43 [I|app|70d88906] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:30:43 +0100
2021-02-25T10:30:43 [I|app|70d88906] Processing by TasksController#show as */*
2021-02-25T10:30:43 [I|app|70d88906]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:30:43 [I|app|70d88906]   Rendered tasks/_list.html.erb (Duration: 4.2ms | Allocations: 5662)
2021-02-25T10:30:43 [I|app|70d88906] Completed 200 OK in 12ms (Views: 4.6ms | ActiveRecord: 1.0ms | Allocations: 7268)
2021-02-25T10:30:44 [I|app|641d6d34] Started GET "/notification_recipients" for 127.0.0.1 at 2021-02-25 10:30:44 +0100
2021-02-25T10:30:44 [I|app|641d6d34] Processing by NotificationRecipientsController#index as JSON
2021-02-25T10:30:44 [D|tax|641d6d34] Current location set to Default Location
2021-02-25T10:30:44 [D|tax|641d6d34] Current organization set to Default Organization
2021-02-25T10:30:44 [D|not|641d6d34] Cache Hit: notification, reading cache for notification-4
2021-02-25T10:30:44 [D|app|641d6d34] Body: {"notifications":[{"id":132,"seen":false,"level":"success","text":"A job 'Gathering facts' has finished successfully","created_at":"2021-02-25T09:30:19.194Z","group":"Jobs","actions":{"links":[{"href":"/job_invocations/130","title":"Job Details"}]}}]}
2021-02-25T10:30:44 [I|app|641d6d34] Completed 200 OK in 8ms (Views: 0.1ms | ActiveRecord: 1.0ms | Allocations: 2240)
2021-02-25T10:30:45 [I|app|efb2195d] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:30:45 +0100
2021-02-25T10:30:45 [I|app|efb2195d] Processing by TasksController#show as */*
2021-02-25T10:30:45 [I|app|efb2195d]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:30:45 [I|app|efb2195d]   Rendered tasks/_list.html.erb (Duration: 4.2ms | Allocations: 5662)
2021-02-25T10:30:45 [I|app|efb2195d] Completed 200 OK in 10ms (Views: 4.7ms | ActiveRecord: 0.9ms | Allocations: 7268)
2021-02-25T10:30:47 [I|app|e11ea6a9] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:30:47 +0100
2021-02-25T10:30:47 [I|app|e11ea6a9] Processing by TasksController#show as */*
2021-02-25T10:30:47 [I|app|e11ea6a9]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:30:47 [I|app|e11ea6a9]   Rendered tasks/_list.html.erb (Duration: 4.5ms | Allocations: 5662)
2021-02-25T10:30:47 [I|app|e11ea6a9] Completed 200 OK in 11ms (Views: 5.0ms | ActiveRecord: 0.9ms | Allocations: 7268)
2021-02-25T10:30:48 [I|app|a54874ad] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:30:48 +0100
2021-02-25T10:30:49 [I|app|a54874ad] Processing by TasksController#show as */*
2021-02-25T10:30:49 [I|app|a54874ad]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:30:49 [I|app|a54874ad]   Rendered tasks/_list.html.erb (Duration: 4.2ms | Allocations: 5662)
2021-02-25T10:30:49 [I|app|a54874ad] Completed 200 OK in 12ms (Views: 4.7ms | ActiveRecord: 1.0ms | Allocations: 7268)
2021-02-25T10:30:50 [I|app|9298732f] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:30:50 +0100
2021-02-25T10:30:50 [I|app|9298732f] Processing by TasksController#show as */*
2021-02-25T10:30:50 [I|app|9298732f]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:30:50 [I|app|9298732f]   Rendered tasks/_list.html.erb (Duration: 4.5ms | Allocations: 5662)
2021-02-25T10:30:50 [I|app|9298732f] Completed 200 OK in 10ms (Views: 5.0ms | ActiveRecord: 0.9ms | Allocations: 7268)
2021-02-25T10:30:52 [I|app|643bf6d6] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:30:52 +0100
2021-02-25T10:30:52 [I|app|643bf6d6] Processing by TasksController#show as */*
2021-02-25T10:30:52 [I|app|643bf6d6]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:30:52 [I|app|643bf6d6]   Rendered tasks/_list.html.erb (Duration: 4.6ms | Allocations: 5662)
2021-02-25T10:30:52 [I|app|643bf6d6] Completed 200 OK in 11ms (Views: 5.0ms | ActiveRecord: 1.0ms | Allocations: 7268)
2021-02-25T10:30:54 [I|app|7effb260] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:30:54 +0100
2021-02-25T10:30:54 [I|app|7effb260] Processing by TasksController#show as */*
2021-02-25T10:30:54 [I|app|7effb260]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:30:54 [I|app|7effb260]   Rendered tasks/_list.html.erb (Duration: 4.3ms | Allocations: 5662)
2021-02-25T10:30:54 [I|app|7effb260] Completed 200 OK in 11ms (Views: 4.7ms | ActiveRecord: 0.9ms | Allocations: 7268)
2021-02-25T10:30:54 [I|app|0da60250] Started GET "/notification_recipients" for 127.0.0.1 at 2021-02-25 10:30:54 +0100
2021-02-25T10:30:54 [I|app|0da60250] Processing by NotificationRecipientsController#index as JSON
2021-02-25T10:30:54 [D|tax|0da60250] Current location set to Default Location
2021-02-25T10:30:54 [D|tax|0da60250] Current organization set to Default Organization
2021-02-25T10:30:54 [D|not|0da60250] Cache Hit: notification, reading cache for notification-4
2021-02-25T10:30:54 [D|app|0da60250] Body: {"notifications":[{"id":132,"seen":false,"level":"success","text":"A job 'Gathering facts' has finished successfully","created_at":"2021-02-25T09:30:19.194Z","group":"Jobs","actions":{"links":[{"href":"/job_invocations/130","title":"Job Details"}]}}]}
2021-02-25T10:30:54 [I|app|0da60250] Completed 200 OK in 38ms (Views: 0.3ms | ActiveRecord: 3.4ms | Allocations: 28553)
2021-02-25T10:30:55 [I|app|fbf3a39d] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:30:55 +0100
2021-02-25T10:30:55 [I|app|fbf3a39d] Processing by TasksController#show as */*
2021-02-25T10:30:55 [I|app|fbf3a39d]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:30:55 [I|app|fbf3a39d]   Rendered tasks/_list.html.erb (Duration: 4.3ms | Allocations: 5662)
2021-02-25T10:30:55 [I|app|fbf3a39d] Completed 200 OK in 11ms (Views: 4.8ms | ActiveRecord: 1.1ms | Allocations: 7268)
2021-02-25T10:30:57 [I|app|bbaa7ae4] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:30:57 +0100
2021-02-25T10:30:57 [I|app|bbaa7ae4] Processing by TasksController#show as */*
2021-02-25T10:30:57 [I|app|bbaa7ae4]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:30:57 [I|app|bbaa7ae4]   Rendered tasks/_list.html.erb (Duration: 4.4ms | Allocations: 5662)
2021-02-25T10:30:57 [I|app|bbaa7ae4] Completed 200 OK in 11ms (Views: 5.0ms | ActiveRecord: 0.9ms | Allocations: 7268)
2021-02-25T10:30:59 [I|app|9e601795] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:30:59 +0100
2021-02-25T10:30:59 [I|app|9e601795] Processing by TasksController#show as */*
2021-02-25T10:30:59 [I|app|9e601795]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:30:59 [I|app|9e601795]   Rendered tasks/_list.html.erb (Duration: 4.3ms | Allocations: 5662)
2021-02-25T10:30:59 [I|app|9e601795] Completed 200 OK in 11ms (Views: 4.8ms | ActiveRecord: 1.0ms | Allocations: 7268)
2021-02-25T10:31:00 [I|app|077f3927] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:31:00 +0100
2021-02-25T10:31:00 [I|app|077f3927] Processing by TasksController#show as */*
2021-02-25T10:31:00 [I|app|077f3927]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:31:00 [I|app|077f3927]   Rendered tasks/_list.html.erb (Duration: 6.3ms | Allocations: 5662)
2021-02-25T10:31:00 [I|app|077f3927] Completed 200 OK in 13ms (Views: 7.0ms | ActiveRecord: 1.0ms | Allocations: 7268)
2021-02-25T10:31:02 [I|app|9b892004] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:31:02 +0100
2021-02-25T10:31:02 [I|app|9b892004] Processing by TasksController#show as */*
2021-02-25T10:31:02 [I|app|9b892004]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:31:02 [I|app|9b892004]   Rendered tasks/_list.html.erb (Duration: 4.4ms | Allocations: 5662)
2021-02-25T10:31:02 [I|app|9b892004] Completed 200 OK in 10ms (Views: 4.8ms | ActiveRecord: 0.8ms | Allocations: 7268)
2021-02-25T10:31:04 [I|app|49f76d59] Started GET "/notification_recipients" for 127.0.0.1 at 2021-02-25 10:31:04 +0100
2021-02-25T10:31:04 [I|app|49f76d59] Processing by NotificationRecipientsController#index as JSON
2021-02-25T10:31:04 [D|tax|49f76d59] Current location set to Default Location
2021-02-25T10:31:04 [D|tax|49f76d59] Current organization set to Default Organization
2021-02-25T10:31:04 [D|not|49f76d59] Cache Hit: notification, reading cache for notification-4
2021-02-25T10:31:04 [D|app|49f76d59] Body: {"notifications":[{"id":132,"seen":false,"level":"success","text":"A job 'Gathering facts' has finished successfully","created_at":"2021-02-25T09:30:19.194Z","group":"Jobs","actions":{"links":[{"href":"/job_invocations/130","title":"Job Details"}]}}]}
2021-02-25T10:31:04 [I|app|49f76d59] Completed 200 OK in 9ms (Views: 0.2ms | ActiveRecord: 1.1ms | Allocations: 2251)
2021-02-25T10:31:04 [I|app|b7376dd9] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:31:04 +0100
2021-02-25T10:31:04 [I|app|b7376dd9] Processing by TasksController#show as */*
2021-02-25T10:31:04 [I|app|b7376dd9]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:31:04 [I|app|b7376dd9]   Rendered tasks/_list.html.erb (Duration: 1.1ms | Allocations: 271)
2021-02-25T10:31:04 [I|app|b7376dd9] Completed 200 OK in 13ms (Views: 4.7ms | ActiveRecord: 1.0ms | Allocations: 2792)
2021-02-25T10:31:05 [I|app|e4e65d0d] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:31:05 +0100
2021-02-25T10:31:05 [I|app|e4e65d0d] Processing by TasksController#show as */*
2021-02-25T10:31:05 [I|app|e4e65d0d]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:31:05 [I|app|e4e65d0d]   Rendered tasks/_list.html.erb (Duration: 4.2ms | Allocations: 5663)
2021-02-25T10:31:05 [I|app|e4e65d0d] Completed 200 OK in 12ms (Views: 4.6ms | ActiveRecord: 1.0ms | Allocations: 7269)
2021-02-25T10:31:07 [I|app|70893499] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:31:07 +0100
2021-02-25T10:31:07 [I|app|70893499] Processing by TasksController#show as */*
2021-02-25T10:31:07 [I|app|70893499]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:31:07 [I|app|70893499]   Rendered tasks/_list.html.erb (Duration: 4.5ms | Allocations: 5662)
2021-02-25T10:31:07 [I|app|70893499] Completed 200 OK in 10ms (Views: 5.0ms | ActiveRecord: 0.9ms | Allocations: 7268)
2021-02-25T10:31:09 [I|app|5694bcfb] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:31:09 +0100
2021-02-25T10:31:09 [I|app|5694bcfb] Processing by TasksController#show as */*
2021-02-25T10:31:09 [I|app|5694bcfb]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:31:09 [I|app|5694bcfb]   Rendered tasks/_list.html.erb (Duration: 4.3ms | Allocations: 5662)
2021-02-25T10:31:09 [I|app|5694bcfb] Completed 200 OK in 12ms (Views: 4.7ms | ActiveRecord: 1.1ms | Allocations: 7268)
2021-02-25T10:31:10 [I|app|88dbd3c4] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:31:10 +0100
2021-02-25T10:31:10 [I|app|88dbd3c4] Processing by TasksController#show as */*
2021-02-25T10:31:10 [I|app|88dbd3c4]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:31:10 [I|app|88dbd3c4]   Rendered tasks/_list.html.erb (Duration: 4.6ms | Allocations: 5662)
2021-02-25T10:31:10 [I|app|88dbd3c4] Completed 200 OK in 10ms (Views: 5.0ms | ActiveRecord: 0.9ms | Allocations: 7268)
2021-02-25T10:31:12 [I|app|ab890023] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:31:12 +0100
2021-02-25T10:31:12 [I|app|ab890023] Processing by TasksController#show as */*
2021-02-25T10:31:12 [I|app|ab890023]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:31:12 [I|app|ab890023]   Rendered tasks/_list.html.erb (Duration: 4.6ms | Allocations: 5662)
2021-02-25T10:31:12 [I|app|ab890023] Completed 200 OK in 11ms (Views: 5.0ms | ActiveRecord: 1.0ms | Allocations: 7268)
2021-02-25T10:31:14 [I|app|844da1a8] Started GET "/notification_recipients" for 127.0.0.1 at 2021-02-25 10:31:14 +0100
2021-02-25T10:31:14 [I|app|844da1a8] Processing by NotificationRecipientsController#index as JSON
2021-02-25T10:31:14 [D|tax|844da1a8] Current location set to Default Location
2021-02-25T10:31:14 [D|tax|844da1a8] Current organization set to Default Organization
2021-02-25T10:31:14 [D|not|844da1a8] Cache Hit: notification, reading cache for notification-4
2021-02-25T10:31:14 [D|app|844da1a8] Body: {"notifications":[{"id":132,"seen":false,"level":"success","text":"A job 'Gathering facts' has finished successfully","created_at":"2021-02-25T09:30:19.194Z","group":"Jobs","actions":{"links":[{"href":"/job_invocations/130","title":"Job Details"}]}}]}
2021-02-25T10:31:14 [I|app|844da1a8] Completed 200 OK in 8ms (Views: 0.1ms | ActiveRecord: 1.0ms | Allocations: 2240)
2021-02-25T10:31:14 [I|app|933cdbab] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:31:14 +0100
2021-02-25T10:31:14 [I|app|933cdbab] Processing by TasksController#show as */*
2021-02-25T10:31:14 [I|app|933cdbab]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:31:14 [I|app|933cdbab]   Rendered tasks/_list.html.erb (Duration: 4.3ms | Allocations: 5662)
2021-02-25T10:31:14 [I|app|933cdbab] Completed 200 OK in 12ms (Views: 4.8ms | ActiveRecord: 1.1ms | Allocations: 7268)
2021-02-25T10:31:15 [I|app|4fbc3c1b] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:31:15 +0100
2021-02-25T10:31:15 [I|app|4fbc3c1b] Processing by TasksController#show as */*
2021-02-25T10:31:15 [I|app|4fbc3c1b]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:31:15 [I|app|4fbc3c1b]   Rendered tasks/_list.html.erb (Duration: 4.3ms | Allocations: 5662)
2021-02-25T10:31:15 [I|app|4fbc3c1b] Completed 200 OK in 11ms (Views: 4.8ms | ActiveRecord: 1.0ms | Allocations: 7268)
2021-02-25T10:31:17 [I|app|2cb33178] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:31:17 +0100
2021-02-25T10:31:17 [I|app|2cb33178] Processing by TasksController#show as */*
2021-02-25T10:31:17 [I|app|2cb33178]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:31:17 [I|app|2cb33178]   Rendered tasks/_list.html.erb (Duration: 4.4ms | Allocations: 5662)
2021-02-25T10:31:17 [I|app|2cb33178] Completed 200 OK in 12ms (Views: 4.8ms | ActiveRecord: 1.1ms | Allocations: 7268)
2021-02-25T10:31:19 [I|app|0be6d09f] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:31:19 +0100
2021-02-25T10:31:19 [I|app|0be6d09f] Processing by TasksController#show as */*
2021-02-25T10:31:19 [I|app|0be6d09f]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:31:19 [I|app|0be6d09f]   Rendered tasks/_list.html.erb (Duration: 4.4ms | Allocations: 5662)
2021-02-25T10:31:19 [I|app|0be6d09f] Completed 200 OK in 12ms (Views: 4.9ms | ActiveRecord: 1.1ms | Allocations: 7268)
2021-02-25T10:31:20 [I|app|c1b433d7] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:31:20 +0100
2021-02-25T10:31:20 [I|app|c1b433d7] Processing by TasksController#show as */*
2021-02-25T10:31:20 [I|app|c1b433d7]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:31:20 [I|app|c1b433d7]   Rendered tasks/_list.html.erb (Duration: 4.2ms | Allocations: 5662)
2021-02-25T10:31:20 [I|app|c1b433d7] Completed 200 OK in 11ms (Views: 4.7ms | ActiveRecord: 1.1ms | Allocations: 7268)
2021-02-25T10:31:22 [I|app|a85119e0] Started GET "/tasks/282a9604-1bc6-4e0f-8a51-34acc63c3333" for 127.0.0.1 at 2021-02-25 10:31:22 +0100
2021-02-25T10:31:22 [I|app|a85119e0] Processing by TasksController#show as */*
2021-02-25T10:31:22 [I|app|a85119e0]   Parameters: {"id"=>"282a9604-1bc6-4e0f-8a51-34acc63c3333"}
2021-02-25T10:31:22 [I|app|a85119e0]   Rendered tasks/_list.html.erb (Duration: 4.5ms | Allocations: 5662)
2021-02-25T10:31:22 [I|app|a85119e0] Completed 200 OK in 11ms (Views: 5.0ms | ActiveRecord: 1.0ms | Allocations: 7268)
2021-02-25T10:31:23 [D|tax|a58a08b8] Current organization set to Default Organization
2021-02-25T10:31:23 [D|tax|a58a08b8] Current location set to Default Location
2021-02-25T10:31:23 [D|tax|a58a08b8] Current location set to none
2021-02-25T10:31:23 [D|tax|a58a08b8] Current organization set to none
2021-02-25T10:31:23 [I|app|a58a08b8] Redirected to https://tfm-01.mydomain.lab/hosts/test-host.mydomain.com
2021-02-25T10:31:23 [D|tax|a58a08b8] Current location set to Default Location
2021-02-25T10:31:23 [D|tax|a58a08b8] Current organization set to Default Organization
2021-02-25T10:31:23 [I|app|a58a08b8] Completed 302 Found in 100221ms (ActiveRecord: 27.4ms | Allocations: 50099)
2021-02-25T10:31:23 [I|app|bf75eb17] Started GET "/hosts/test-host.mydomain.com" for 127.0.0.1 at 2021-02-25 10:31:23 +0100
2021-02-25T10:31:23 [I|app|bf75eb17] Processing by HostsController#show as */*
2021-02-25T10:31:23 [I|app|bf75eb17]   Parameters: {"id"=>"test-host.mydomain.com"}
2021-02-25T10:31:23 [D|tax|bf75eb17] Current location set to Default Location
2021-02-25T10:31:23 [D|tax|bf75eb17] Current organization set to Default Organization
2021-02-25T10:31:23 [I|app|bf75eb17]   Rendering hosts/show.html.erb within layouts/application
2021-02-25T10:31:23 [D|tax|bf75eb17] Current organization set to Default Organization
2021-02-25T10:31:23 [D|tax|bf75eb17] Current location set to Default Location
2021-02-25T10:31:23 [D|tax|bf75eb17] Current location set to Default Location
2021-02-25T10:31:23 [D|tax|bf75eb17] Current organization set to Default Organization
2021-02-25T10:31:23 [I|app|bf75eb17]   Rendered hosts/_registration_tab.html.erb (Duration: 18.9ms | Allocations: 11357)
2021-02-25T10:31:23 [I|app|bf75eb17]   Rendered hosts/show.html.erb within layouts/application (Duration: 46.5ms | Allocations: 29910)
2021-02-25T10:31:23 [I|app|bf75eb17]   Rendered layouts/_application_content.html.erb (Duration: 2.0ms | Allocations: 5854)
2021-02-25T10:31:23 [I|app|bf75eb17]   Rendering layouts/base.html.erb
2021-02-25T10:31:23 [I|app|bf75eb17]   Rendered layouts/base.html.erb (Duration: 13.0ms | Allocations: 23400)
2021-02-25T10:31:23 [I|app|bf75eb17] Completed 200 OK in 78ms (Views: 49.5ms | ActiveRecord: 18.1ms | Allocations: 70097)
2021-02-25T10:31:24 [I|app|8d1a9c03] Started GET "/notification_recipients" for 127.0.0.1 at 2021-02-25 10:31:24 +0100
2021-02-25T10:31:24 [I|app|9bbd17e6] Started GET "/hosts/test-host.mydomain.com/overview" for 127.0.0.1 at 2021-02-25 10:31:24 +0100
2021-02-25T10:31:24 [I|app|8d1a9c03] Processing by NotificationRecipientsController#index as JSON
2021-02-25T10:31:24 [I|app|9bbd17e6] Processing by HostsController#overview as HTML
2021-02-25T10:31:24 [I|app|9bbd17e6]   Parameters: {"id"=>"test-host.mydomain.com"}
2021-02-25T10:31:24 [D|tax|8d1a9c03] Current location set to Default Location
2021-02-25T10:31:24 [D|tax|9bbd17e6] Current location set to Default Location
2021-02-25T10:31:24 [D|tax|8d1a9c03] Current organization set to Default Organization
2021-02-25T10:31:24 [D|not|8d1a9c03] Cache Hit: notification, reading cache for notification-4
2021-02-25T10:31:24 [D|app|8d1a9c03] Body: {"notifications":[{"id":132,"seen":false,"level":"success","text":"A job 'Gathering facts' has finished successfully","created_at":"2021-02-25T09:30:19.194Z","group":"Jobs","actions":{"links":[{"href":"/job_invocations/130","title":"Job Details"}]}}]}
2021-02-25T10:31:24 [I|app|8d1a9c03] Completed 200 OK in 9ms (Views: 0.1ms | ActiveRecord: 1.1ms | Allocations: 2412)
2021-02-25T10:31:24 [D|tax|9bbd17e6] Current organization set to Default Organization
2021-02-25T10:31:24 [I|app|9bbd17e6]   Rendered hosts/_overview.html.erb (Duration: 29.1ms | Allocations: 10646)
2021-02-25T10:31:24 [I|app|9bbd17e6] Completed 200 OK in 44ms (Views: 21.2ms | ActiveRecord: 11.6ms | Allocations: 15151)
2021-02-25T10:31:24 [I|app|9adbe4b9] Started GET "/hosts/test-host.mydomain.com/templates" for 127.0.0.1 at 2021-02-25 10:31:24 +0100
2021-02-25T10:31:24 [I|app|505bba7d] Started GET "/hosts/test-host.mydomain.com/resources?range=7" for 127.0.0.1 at 2021-02-25 10:31:24 +0100
2021-02-25T10:31:24 [I|app|9adbe4b9] Processing by HostsController#templates as HTML
2021-02-25T10:31:24 [I|app|9adbe4b9]   Parameters: {"id"=>"test-host.mydomain.com"}
2021-02-25T10:31:24 [I|app|505bba7d] Processing by HostsController#resources as HTML
2021-02-25T10:31:24 [I|app|505bba7d]   Parameters: {"range"=>"7", "id"=>"test-host.mydomain.com"}
2021-02-25T10:31:24 [I|app|992bfc31] Started GET "/hosts/test-host.mydomain.com/nics" for 127.0.0.1 at 2021-02-25 10:31:24 +0100
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current location set to Default Location
2021-02-25T10:31:24 [D|tax|505bba7d] Current location set to Default Location
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current organization set to Default Organization
2021-02-25T10:31:24 [D|tax|505bba7d] Current organization set to Default Organization
2021-02-25T10:31:24 [I|app|992bfc31] Processing by HostsController#nics as HTML
2021-02-25T10:31:24 [I|app|992bfc31]   Parameters: {"id"=>"test-host.mydomain.com"}
2021-02-25T10:31:24 [I|app|5fef6647] Started GET "/hosts/test-host.mydomain.com/runtime?range=7" for 127.0.0.1 at 2021-02-25 10:31:24 +0100
2021-02-25T10:31:24 [D|tax|992bfc31] Current location set to Default Location
2021-02-25T10:31:24 [D|tax|992bfc31] Current organization set to Default Organization
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current organization set to Default Organization
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current location set to Default Location
2021-02-25T10:31:24 [I|app|505bba7d]   Rendered hosts/_resources.html.erb (Duration: 3.1ms | Allocations: 1401)
2021-02-25T10:31:24 [I|app|505bba7d] Completed 200 OK in 17ms (Views: 3.0ms | ActiveRecord: 4.3ms | Allocations: 6916)
2021-02-25T10:31:24 [I|app|5fef6647] Processing by HostsController#runtime as HTML
2021-02-25T10:31:24 [I|app|5fef6647]   Parameters: {"range"=>"7", "id"=>"test-host.mydomain.com"}
2021-02-25T10:31:24 [I|app|992bfc31]   Rendered hosts/_nics.html.erb (Duration: 9.0ms | Allocations: 4827)
2021-02-25T10:31:24 [I|app|992bfc31] Completed 200 OK in 21ms (Views: 8.2ms | ActiveRecord: 3.3ms | Allocations: 9349)
2021-02-25T10:31:24 [D|tax|5fef6647] Current location set to Default Location
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current location set to Default Location
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current organization set to Default Organization
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current organization set to Default Organization
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current location set to Default Location
2021-02-25T10:31:24 [D|tax|5fef6647] Current organization set to Default Organization
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current location set to Default Location
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current organization set to Default Organization
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current organization set to Default Organization
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current location set to Default Location
2021-02-25T10:31:24 [I|app|5fef6647]   Rendered hosts/_runtime.html.erb (Duration: 2.1ms | Allocations: 1019)
2021-02-25T10:31:24 [I|app|5fef6647] Completed 200 OK in 13ms (Views: 2.3ms | ActiveRecord: 3.1ms | Allocations: 5628)
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current location set to Default Location
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current organization set to Default Organization
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current organization set to Default Organization
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current location set to Default Location
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current location set to Default Location
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current organization set to Default Organization
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current organization set to Default Organization
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current location set to Default Location
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current location set to Default Location
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current organization set to Default Organization
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current organization set to Default Organization
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current location set to Default Location
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current location set to Default Location
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current organization set to Default Organization
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current organization set to Default Organization
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current location set to Default Location
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current location set to Default Location
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current organization set to Default Organization
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current organization set to Default Organization
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current location set to Default Location
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current location set to Default Location
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current organization set to Default Organization
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current organization set to Default Organization
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current location set to Default Location
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current location set to Default Location
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current organization set to Default Organization
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current organization set to Default Organization
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current location set to Default Location
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current location set to Default Location
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current organization set to Default Organization
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current organization set to Default Organization
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current location set to Default Location
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current location set to Default Location
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current organization set to Default Organization
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current organization set to Default Organization
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current location set to Default Location
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current location set to Default Location
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current organization set to Default Organization
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current organization set to Default Organization
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current location set to Default Location
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current location set to Default Location
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current organization set to Default Organization
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current organization set to Default Organization
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current location set to Default Location
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current location set to Default Location
2021-02-25T10:31:24 [D|tax|9adbe4b9] Current organization set to Default Organization
2021-02-25T10:31:24 [I|app|9adbe4b9]   Rendered hosts/_templates.html.erb (Duration: 10.4ms | Allocations: 5340)
2021-02-25T10:31:24 [I|app|9adbe4b9] Completed 200 OK in 151ms (Views: 10.5ms | ActiveRecord: 51.0ms | Allocations: 77596)

/var/log/foreman-proxy/proxy.log

2021-02-25T10:28:59  [D] Rack::Handler::WEBrick is mounted on /.
2021-02-25T10:28:59  [I] WEBrick::HTTPServer#start: pid=7468 port=8443
2021-02-25T10:28:59  [I] Smart proxy has launched on 1 socket(s), waiting for requests

mike1260 · February 25, 2021, 2:00pm

While trying to investigate the issue, I stumbled on a interesting parameter in foreman settings under Provisioning > DNS timeout.

I tried to change the value to 1

Then edited my host and an error occur as soon as I clicked on the save button

Oops, we're sorry but something went wrong "1" is not numeric

Below the logs

2021-02-25T14:51:22 [I|app|44109e12]   Parameters: {"utf8"=>"✓", "authenticity_token"=>"[FILTERED]", "host"=>{"name"=>"test-host", "hostgroup_id"=>"1", "environment_id"=>"1", "puppet_proxy_id"=>"1", "puppet_ca_proxy_id"=>"1", "ansible_role_ids"=>[""], "puppetclass_ids"=>[""], "managed"=>"true", "progress_report_id"=>"[FILTERED]", "interfaces_attributes"=>{"0"=>{"_destroy"=>"0", "mac"=>"00:0c:29:20:c8:5e", "identifier"=>"ens160", "name"=>"test-host", "domain_id"=>"2", "subnet_id"=>"1", "ip"=>"172.22.63.170", "ip6"=>"", "managed"=>"1", "primary"=>"1", "provision"=>"1", "execution"=>"1", "tag"=>"", "attached_to"=>"", "id"=>"18"}}, "architecture_id"=>"1", "operatingsystem_id"=>"3", "medium_id"=>"14", "ptable_id"=>"166", "pxe_loader"=>"Grub2 UEFI", "disk"=>"", "is_owned_by"=>"4-Users", "enabled"=>"1", "model_id"=>"", "comment"=>"", "overwrite"=>"false"}, "id"=>"10"}
2021-02-25T14:51:22 [W|app|44109e12] "1" is not numeric
2021-02-25T14:51:22 [I|app|44109e12] Backtrace for '"1" is not numeric' error (ArgumentError): "1" is not numeric
 44109e12 | /usr/share/ruby/resolv.rb:954:in `block in timeouts='
 44109e12 | /usr/share/ruby/resolv.rb:953:in `each'
 44109e12 | /usr/share/ruby/resolv.rb:953:in `timeouts='
 44109e12 | /usr/share/ruby/resolv.rb:351:in `timeouts='
 44109e12 | /usr/share/foreman/lib/net/dns.rb:25:in `lookup'
 44109e12 | /usr/share/foreman/lib/net/dns.rb:84:in `dns_lookup'
 44109e12 | /usr/share/foreman/lib/net/dns/forward_record.rb:22:in `conflicts'
 44109e12 | /usr/share/foreman/lib/net.rb:23:in `conflicting?'
 44109e12 | /usr/share/foreman/app/models/concerns/orchestration/dns.rb:119:in `block in dns_conflict_detected?'
 44109e12 | /usr/share/foreman/app/models/concerns/orchestration/dns.rb:118:in `each'
 44109e12 | /usr/share/foreman/app/models/concerns/orchestration/dns.rb:118:in `dns_conflict_detected?'
 44109e12 | /usr/share/gems/gems/activesupport-6.0.3.4/lib/active_support/callbacks.rb:428:in `block in make_lambda'
 44109e12 | /usr/share/gems/gems/activesupport-6.0.3.4/lib/active_support/callbacks.rb:238:in `block in halting_and_conditional'
 44109e12 | /usr/share/gems/gems/activesupport-6.0.3.4/lib/active_support/callbacks.rb:517:in `block in invoke_after'
 44109e12 | /usr/share/gems/gems/activesupport-6.0.3.4/lib/active_support/callbacks.rb:517:in `each'
 44109e12 | /usr/share/gems/gems/activesupport-6.0.3.4/lib/active_support/callbacks.rb:517:in `invoke_after'
 44109e12 | /usr/share/gems/gems/activesupport-6.0.3.4/lib/active_support/callbacks.rb:136:in `run_callbacks'
 44109e12 | /usr/share/gems/gems/activesupport-6.0.3.4/lib/active_support/callbacks.rb:825:in `_run_validation_callbacks'
 44109e12 | /usr/share/gems/gems/activemodel-6.0.3.4/lib/active_model/validations/callbacks.rb:117:in `run_validations!'
 44109e12 | /usr/share/gems/gems/activemodel-6.0.3.4/lib/active_model/validations.rb:337:in `valid?'
 44109e12 | /usr/share/gems/gems/activerecord-6.0.3.4/lib/active_record/validations.rb:68:in `valid?'
 44109e12 | /usr/share/foreman/app/models/concerns/orchestration.rb:86:in `valid?'
 44109e12 | /usr/share/gems/gems/activerecord-6.0.3.4/lib/active_record/autosave_association.rb:327:in `association_valid?'
 44109e12 | /usr/share/gems/gems/activerecord-6.0.3.4/lib/active_record/autosave_association.rb:314:in `block in validate_collection_association'
 44109e12 | /usr/share/gems/gems/activerecord-6.0.3.4/lib/active_record/autosave_association.rb:314:in `each'
 44109e12 | /usr/share/gems/gems/activerecord-6.0.3.4/lib/active_record/autosave_association.rb:314:in `each_with_index'
 44109e12 | /usr/share/gems/gems/activerecord-6.0.3.4/lib/active_record/autosave_association.rb:314:in `validate_collection_association'
 44109e12 | /usr/share/gems/gems/activerecord-6.0.3.4/lib/active_record/autosave_association.rb:219:in `block in define_autosave_validation_callbacks'
 44109e12 | /usr/share/gems/gems/activerecord-6.0.3.4/lib/active_record/autosave_association.rb:158:in `instance_eval'
 44109e12 | /usr/share/gems/gems/activerecord-6.0.3.4/lib/active_record/autosave_association.rb:158:in `block in define_non_cyclic_method'
 44109e12 | /usr/share/gems/gems/activesupport-6.0.3.4/lib/active_support/callbacks.rb:428:in `block in make_lambda'
 44109e12 | /usr/share/gems/gems/activesupport-6.0.3.4/lib/active_support/callbacks.rb:200:in `block (2 levels) in halting'
 44109e12 | /usr/share/gems/gems/activesupport-6.0.3.4/lib/active_support/callbacks.rb:605:in `block (2 levels) in default_terminator'
 44109e12 | /usr/share/gems/gems/activesupport-6.0.3.4/lib/active_support/callbacks.rb:604:in `catch'
 44109e12 | /usr/share/gems/gems/activesupport-6.0.3.4/lib/active_support/callbacks.rb:604:in `block in default_terminator'
 44109e12 | /usr/share/gems/gems/activesupport-6.0.3.4/lib/active_support/callbacks.rb:201:in `block in halting'
 44109e12 | /usr/share/gems/gems/activesupport-6.0.3.4/lib/active_support/callbacks.rb:513:in `block in invoke_before'
 44109e12 | /usr/share/gems/gems/activesupport-6.0.3.4/lib/active_support/callbacks.rb:513:in `each'
 44109e12 | /usr/share/gems/gems/activesupport-6.0.3.4/lib/active_support/callbacks.rb:513:in `invoke_before'
 44109e12 | /usr/share/gems/gems/activesupport-6.0.3.4/lib/active_support/callbacks.rb:134:in `run_callbacks'
 44109e12 | /usr/share/gems/gems/activesupport-6.0.3.4/lib/active_support/callbacks.rb:825:in `_run_validate_callbacks'
 44109e12 | /usr/share/gems/gems/activemodel-6.0.3.4/lib/active_model/validations.rb:406:in `run_validations!'
 44109e12 | /usr/share/gems/gems/activemodel-6.0.3.4/lib/active_model/validations/callbacks.rb:117:in `block in run_validations!'
 44109e12 | /usr/share/gems/gems/activesupport-6.0.3.4/lib/active_support/callbacks.rb:135:in `run_callbacks'
 44109e12 | /usr/share/gems/gems/activesupport-6.0.3.4/lib/active_support/callbacks.rb:825:in `_run_validation_callbacks'
 44109e12 | /usr/share/gems/gems/activemodel-6.0.3.4/lib/active_model/validations/callbacks.rb:117:in `run_validations!'
 44109e12 | /usr/share/gems/gems/activemodel-6.0.3.4/lib/active_model/validations.rb:337:in `valid?'
 44109e12 | /usr/share/gems/gems/activerecord-6.0.3.4/lib/active_record/validations.rb:68:in `valid?'
 44109e12 | /usr/share/foreman/app/models/concerns/orchestration.rb:86:in `valid?'
 44109e12 | /usr/share/gems/gems/activerecord-6.0.3.4/lib/active_record/validations.rb:84:in `perform_validations'
 44109e12 | /usr/share/gems/gems/activerecord-6.0.3.4/lib/active_record/validations.rb:47:in `save'
 44109e12 | /usr/share/gems/gems/activerecord-6.0.3.4/lib/active_record/transactions.rb:314:in `block in save'
 44109e12 | /usr/share/gems/gems/activerecord-6.0.3.4/lib/active_record/transactions.rb:375:in `block in with_transaction_returning_status'
 44109e12 | /usr/share/gems/gems/activerecord-6.0.3.4/lib/active_record/connection_adapters/abstract/database_statements.rb:278:in `transaction'
 44109e12 | /usr/share/gems/gems/activerecord-6.0.3.4/lib/active_record/transactions.rb:212:in `transaction'
 44109e12 | /usr/share/gems/gems/activerecord-6.0.3.4/lib/active_record/transactions.rb:366:in `with_transaction_returning_status'
 44109e12 | /usr/share/gems/gems/activerecord-6.0.3.4/lib/active_record/transactions.rb:314:in `save'
 44109e12 | /usr/share/gems/gems/activerecord-6.0.3.4/lib/active_record/suppressor.rb:44:in `save'
 44109e12 | /usr/share/foreman/app/models/concerns/foreman/sti.rb:26:in `save'
 44109e12 | /usr/share/gems/gems/activerecord-6.0.3.4/lib/active_record/persistence.rb:621:in `block in update'
 44109e12 | /usr/share/gems/gems/activerecord-6.0.3.4/lib/active_record/transactions.rb:375:in `block in with_transaction_returning_status'
 44109e12 | /usr/share/gems/gems/activerecord-6.0.3.4/lib/active_record/connection_adapters/abstract/database_statements.rb:280:in `block in transaction'
 44109e12 | /usr/share/gems/gems/activerecord-6.0.3.4/lib/active_record/connection_adapters/abstract/transaction.rb:280:in `block in within_new_transaction'
 44109e12 | /usr/share/gems/gems/activesupport-6.0.3.4/lib/active_support/concurrency/load_interlock_aware_monitor.rb:26:in `block (2 levels) in synchronize'
 44109e12 | /usr/share/gems/gems/activesupport-6.0.3.4/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `handle_interrupt'
 44109e12 | /usr/share/gems/gems/activesupport-6.0.3.4/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `block in synchronize'
 44109e12 | /usr/share/gems/gems/activesupport-6.0.3.4/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'
 44109e12 | /usr/share/gems/gems/activesupport-6.0.3.4/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'
 44109e12 | /usr/share/gems/gems/activerecord-6.0.3.4/lib/active_record/connection_adapters/abstract/transaction.rb:278:in `within_new_transaction'
 44109e12 | /usr/share/gems/gems/activerecord-6.0.3.4/lib/active_record/connection_adapters/abstract/database_statements.rb:280:in `transaction'
 44109e12 | /usr/share/gems/gems/activerecord-6.0.3.4/lib/active_record/transactions.rb:212:in `transaction'
 44109e12 | /usr/share/gems/gems/activerecord-6.0.3.4/lib/active_record/transactions.rb:366:in `with_transaction_returning_status'
 44109e12 | /usr/share/gems/gems/activerecord-6.0.3.4/lib/active_record/persistence.rb:619:in `update'
 44109e12 | /usr/share/foreman/app/controllers/hosts_controller.rb:116:in `block in update'
 44109e12 | /usr/share/foreman/app/models/taxonomy.rb:76:in `block in no_taxonomy_scope'
 44109e12 | /usr/share/foreman/app/models/taxonomy.rb:83:in `block (2 levels) in as_taxonomy'
 44109e12 | /usr/share/foreman/app/models/concerns/foreman/thread_session.rb:195:in `as_location'
 44109e12 | /usr/share/foreman/app/models/taxonomy.rb:82:in `block in as_taxonomy'
 44109e12 | /usr/share/foreman/app/models/concerns/foreman/thread_session.rb:154:in `as_org'
 44109e12 | /usr/share/foreman/app/models/taxonomy.rb:81:in `as_taxonomy'
 44109e12 | /usr/share/foreman/app/models/taxonomy.rb:75:in `no_taxonomy_scope'
 44109e12 | /usr/share/foreman/app/controllers/hosts_controller.rb:113:in `update'
 44109e12 | /usr/share/gems/gems/actionpack-6.0.3.4/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
 44109e12 | /usr/share/gems/gems/actionpack-6.0.3.4/lib/abstract_controller/base.rb:195:in `process_action'
 44109e12 | /usr/share/gems/gems/actionpack-6.0.3.4/lib/action_controller/metal/rendering.rb:30:in `process_action'
 44109e12 | /usr/share/gems/gems/actionpack-6.0.3.4/lib/abstract_controller/callbacks.rb:42:in `block in process_action'
 44109e12 | /usr/share/gems/gems/activesupport-6.0.3.4/lib/active_support/callbacks.rb:112:in `block in run_callbacks'
 44109e12 | /usr/share/foreman/app/controllers/concerns/foreman/controller/timezone.rb:10:in `set_timezone'
 44109e12 | /usr/share/gems/gems/activesupport-6.0.3.4/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
 44109e12 | /usr/share/foreman/app/models/concerns/foreman/thread_session.rb:32:in `clear_thread'
 44109e12 | /usr/share/gems/gems/activesupport-6.0.3.4/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
 44109e12 | /usr/share/foreman/app/controllers/concerns/foreman/controller/topbar_sweeper.rb:12:in `set_topbar_sweeper_controller'
 44109e12 | /usr/share/gems/gems/activesupport-6.0.3.4/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
 44109e12 | /usr/share/gems/gems/audited-4.9.0/lib/audited/sweeper.rb:14:in `around'
 44109e12 | /usr/share/gems/gems/activesupport-6.0.3.4/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
 44109e12 | /usr/share/gems/gems/audited-4.9.0/lib/audited/sweeper.rb:14:in `around'
 44109e12 | /usr/share/gems/gems/activesupport-6.0.3.4/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
 44109e12 | /usr/share/gems/gems/activesupport-6.0.3.4/lib/active_support/callbacks.rb:139:in `run_callbacks'
 44109e12 | /usr/share/gems/gems/actionpack-6.0.3.4/lib/abstract_controller/callbacks.rb:41:in `process_action'
 44109e12 | /usr/share/gems/gems/actionpack-6.0.3.4/lib/action_controller/metal/rescue.rb:22:in `process_action'
 44109e12 | /usr/share/gems/gems/actionpack-6.0.3.4/lib/action_controller/metal/instrumentation.rb:33:in `block in process_action'
 44109e12 | /usr/share/gems/gems/activesupport-6.0.3.4/lib/active_support/notifications.rb:180:in `block in instrument'
 44109e12 | /usr/share/gems/gems/activesupport-6.0.3.4/lib/active_support/notifications/instrumenter.rb:24:in `instrument'
 44109e12 | /usr/share/gems/gems/activesupport-6.0.3.4/lib/active_support/notifications.rb:180:in `instrument'
 44109e12 | /usr/share/gems/gems/actionpack-6.0.3.4/lib/action_controller/metal/instrumentation.rb:32:in `process_action'
 44109e12 | /usr/share/gems/gems/actionpack-6.0.3.4/lib/action_controller/metal/params_wrapper.rb:245:in `process_action'
 44109e12 | /usr/share/gems/gems/activerecord-6.0.3.4/lib/active_record/railties/controller_runtime.rb:27:in `process_action'
 44109e12 | /usr/share/gems/gems/actionpack-6.0.3.4/lib/abstract_controller/base.rb:136:in `process'
 44109e12 | /usr/share/gems/gems/actionview-6.0.3.4/lib/action_view/rendering.rb:39:in `process'
 44109e12 | /usr/share/gems/gems/actionpack-6.0.3.4/lib/action_controller/metal.rb:190:in `dispatch'
 44109e12 | /usr/share/gems/gems/actionpack-6.0.3.4/lib/action_controller/metal.rb:254:in `dispatch'
 44109e12 | /usr/share/gems/gems/actionpack-6.0.3.4/lib/action_dispatch/routing/route_set.rb:50:in `dispatch'
 44109e12 | /usr/share/gems/gems/actionpack-6.0.3.4/lib/action_dispatch/routing/route_set.rb:33:in `serve'
 44109e12 | /usr/share/gems/gems/actionpack-6.0.3.4/lib/action_dispatch/journey/router.rb:49:in `block in serve'
 44109e12 | /usr/share/gems/gems/actionpack-6.0.3.4/lib/action_dispatch/journey/router.rb:32:in `each'
 44109e12 | /usr/share/gems/gems/actionpack-6.0.3.4/lib/action_dispatch/journey/router.rb:32:in `serve'
 44109e12 | /usr/share/gems/gems/actionpack-6.0.3.4/lib/action_dispatch/routing/route_set.rb:834:in `call'
 44109e12 | /usr/share/gems/gems/apipie-dsl-2.3.0/lib/apipie_dsl/static_dispatcher.rb:67:in `call'
 44109e12 | /usr/share/gems/gems/apipie-rails-0.5.17/lib/apipie/static_dispatcher.rb:66:in `call'
 44109e12 | /usr/share/gems/gems/apipie-rails-0.5.17/lib/apipie/extractor/recorder.rb:137:in `call'
 44109e12 | /usr/share/gems/gems/actionpack-6.0.3.4/lib/action_dispatch/middleware/static.rb:126:in `call'
 44109e12 | /usr/share/gems/gems/actionpack-6.0.3.4/lib/action_dispatch/middleware/static.rb:126:in `call'
 44109e12 | /usr/share/gems/gems/actionpack-6.0.3.4/lib/action_dispatch/middleware/static.rb:126:in `call'
 44109e12 | /usr/share/gems/gems/actionpack-6.0.3.4/lib/action_dispatch/middleware/static.rb:126:in `call'
 44109e12 | /usr/share/gems/gems/actionpack-6.0.3.4/lib/action_dispatch/middleware/static.rb:126:in `call'
 44109e12 | /usr/share/gems/gems/actionpack-6.0.3.4/lib/action_dispatch/middleware/static.rb:126:in `call'
 44109e12 | /usr/share/gems/gems/actionpack-6.0.3.4/lib/action_dispatch/middleware/static.rb:126:in `call'
 44109e12 | /usr/share/foreman/lib/foreman/middleware/telemetry.rb:10:in `call'
 44109e12 | /usr/share/gems/gems/apipie-rails-0.5.17/lib/apipie/middleware/checksum_in_headers.rb:27:in `call'
 44109e12 | /usr/share/foreman/lib/foreman/middleware/catch_json_parse_errors.rb:9:in `call'
 44109e12 | /usr/share/gems/gems/rack-2.2.3/lib/rack/tempfile_reaper.rb:15:in `call'
 44109e12 | /usr/share/gems/gems/rack-2.2.3/lib/rack/etag.rb:27:in `call'
 44109e12 | /usr/share/gems/gems/rack-2.2.3/lib/rack/conditional_get.rb:40:in `call'
 44109e12 | /usr/share/gems/gems/rack-2.2.3/lib/rack/head.rb:12:in `call'
 44109e12 | /usr/share/gems/gems/actionpack-6.0.3.4/lib/action_dispatch/http/content_security_policy.rb:18:in `call'
 44109e12 | /usr/share/foreman/lib/foreman/middleware/logging_context_session.rb:22:in `call'
 44109e12 | /usr/share/gems/gems/rack-2.2.3/lib/rack/session/abstract/id.rb:266:in `context'
 44109e12 | /usr/share/gems/gems/rack-2.2.3/lib/rack/session/abstract/id.rb:260:in `call'
 44109e12 | /usr/share/gems/gems/actionpack-6.0.3.4/lib/action_dispatch/middleware/cookies.rb:648:in `call'
 44109e12 | /usr/share/gems/gems/actionpack-6.0.3.4/lib/action_dispatch/middleware/callbacks.rb:27:in `block in call'
 44109e12 | /usr/share/gems/gems/activesupport-6.0.3.4/lib/active_support/callbacks.rb:101:in `run_callbacks'
 44109e12 | /usr/share/gems/gems/actionpack-6.0.3.4/lib/action_dispatch/middleware/callbacks.rb:26:in `call'
 44109e12 | /usr/share/gems/gems/actionpack-6.0.3.4/lib/action_dispatch/middleware/actionable_exceptions.rb:18:in `call'
 44109e12 | /usr/share/gems/gems/actionpack-6.0.3.4/lib/action_dispatch/middleware/debug_exceptions.rb:32:in `call'
 44109e12 | /usr/share/gems/gems/actionpack-6.0.3.4/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
 44109e12 | /usr/share/gems/gems/railties-6.0.3.4/lib/rails/rack/logger.rb:37:in `call_app'
 44109e12 | /usr/share/gems/gems/railties-6.0.3.4/lib/rails/rack/logger.rb:28:in `call'
 44109e12 | /usr/share/gems/gems/sprockets-rails-3.2.1/lib/sprockets/rails/quiet_assets.rb:13:in `call'
 44109e12 | /usr/share/foreman/lib/foreman/middleware/logging_context_request.rb:11:in `call'
 44109e12 | /usr/share/gems/gems/actionpack-6.0.3.4/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
 44109e12 | /usr/share/gems/gems/actionpack-6.0.3.4/lib/action_dispatch/middleware/request_id.rb:27:in `call'
 44109e12 | /usr/share/gems/gems/rack-2.2.3/lib/rack/method_override.rb:24:in `call'
 44109e12 | /usr/share/gems/gems/rack-2.2.3/lib/rack/runtime.rb:22:in `call'
 44109e12 | /usr/share/gems/gems/activesupport-6.0.3.4/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
 44109e12 | /usr/share/gems/gems/actionpack-6.0.3.4/lib/action_dispatch/middleware/executor.rb:14:in `call'
 44109e12 | /usr/share/gems/gems/actionpack-6.0.3.4/lib/action_dispatch/middleware/static.rb:126:in `call'
 44109e12 | /usr/share/gems/gems/rack-2.2.3/lib/rack/sendfile.rb:110:in `call'
 44109e12 | /usr/share/gems/gems/actionpack-6.0.3.4/lib/action_dispatch/middleware/host_authorization.rb:76:in `call'
 44109e12 | /usr/share/gems/gems/secure_headers-6.3.0/lib/secure_headers/middleware.rb:11:in `call'
 44109e12 | /usr/share/gems/gems/railties-6.0.3.4/lib/rails/engine.rb:527:in `call'
 44109e12 | /usr/share/gems/gems/railties-6.0.3.4/lib/rails/railtie.rb:190:in `public_send'
 44109e12 | /usr/share/gems/gems/railties-6.0.3.4/lib/rails/railtie.rb:190:in `method_missing'
 44109e12 | /usr/share/gems/gems/rack-2.2.3/lib/rack/urlmap.rb:74:in `block in call'
 44109e12 | /usr/share/gems/gems/rack-2.2.3/lib/rack/urlmap.rb:58:in `each'
 44109e12 | /usr/share/gems/gems/rack-2.2.3/lib/rack/urlmap.rb:58:in `call'
 44109e12 | /usr/share/gems/gems/puma-5.1.1/lib/puma/configuration.rb:246:in `call'
 44109e12 | /usr/share/gems/gems/puma-5.1.1/lib/puma/request.rb:76:in `block in handle_request'
 44109e12 | /usr/share/gems/gems/puma-5.1.1/lib/puma/thread_pool.rb:337:in `with_force_shutdown'
 44109e12 | /usr/share/gems/gems/puma-5.1.1/lib/puma/request.rb:75:in `handle_request'
 44109e12 | /usr/share/gems/gems/puma-5.1.1/lib/puma/server.rb:431:in `process_client'
 44109e12 | /usr/share/gems/gems/puma-5.1.1/lib/puma/thread_pool.rb:145:in `block in spawn_thread'
 44109e12 | /usr/share/gems/gems/logging-2.3.0/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
2021-02-25T14:51:22 [I|app|44109e12]   Rendering common/500.html.erb
2021-02-25T14:51:22 [I|app|44109e12]   Rendered common/500.html.erb (Duration: 3.6ms | Allocations: 6171)
2021-02-25T14:51:22 [I|app|44109e12] Completed 500 Internal Server Error in 51ms (Views: 4.1ms | ActiveRecord: 9.3ms | Allocations: 31323)

So I decided to revert back to the default values which was “5,10,15,20”

But this time, despite the default value it failed to edit the host and spit out the same error message

 Oops, we're sorry but something went wrong "5" is not numeric

I’m now wondering if the initial issue that I have could be related to dns timeout

Thanks for your help.

mike1260 · February 25, 2021, 2:28pm

Found the issue I guess

Hi again,

I think I have found the issue.

Base on the dns timeout error that I got, I decided to revert my vm snapshot that I created before modifying the dns timeout option in Foreman settings.

Then, I edited my /etc/resolv.conf and changed the nameserver to an other one which is not the dns server to were I want foreman to manage the dns.

After that, I re-set the DNS proxy in my (mydomain.com), then edited my host and it work perfectly without any slow issue

Now, what could cause this issue with my dns server and foreman ?

The dns server is very fast, here’s below a simple dig query

dig @172.22.63.17 test-host.mydomain.com

; <<>> DiG 9.11.20-RedHat-9.11.20-5.el8 <<>> @172.22.63.17 test-host.mydomain.com
; (1 server found)
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 36761
;; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 512
;; QUESTION SECTION:
;test-host.mydomain.com.          IN      A

;; ANSWER SECTION:
test-host.mydomain.com.   86400   IN      A       172.22.63.170

;; Query time: 2 msec
;; SERVER: 172.22.63.17#53(172.22.63.17)
;; WHEN: Thu Feb 25 15:26:41 CET 2021
;; MSG SIZE  rcvd: 65

mike1260 · February 25, 2021, 2:49pm

Partially resolved

In foreman settings under Provisioning , I set Query local nameservers to true then I re-added my powerdns name servers I now everything is working as expected.

However, Provisioning > DNS timeout remain unresolved.

Hope it helps.

lzap · March 2, 2021, 12:49pm

So I read you figured it out, sorry for the late reply I was busy. Yes, by default Foreman attempts to reach out to the DNS smart proxy, we assume that it’s open for queries. On some deployments firewalls might block this. Thus the option you have found out, then Foreman uses the OS resolver. We slightly improved logging in the last version so it should be at least obvious when you run into this.

This looks like some bug, this setting was initially a number but it was recently upgraded to an array, can you try to enter [5, 5, 10, 10]? This will make the DNS stack to wait 5 seconds twice and then 10 and then error out. Perhaps this was an upgraded instance when it accepted the number but now when you try to enter it back it forces you to enter array. See the description “List of…”.

mike1260 · March 3, 2021, 6:54am

Hello,

thank you for your reply. Delay was expected, so no worries

Indeed this wasn’t clear, that’s good to know. Thanks.

Currently using the instance, so can’t really modify this value in case if it fail again.

The server was first installed with foreman-2.4.0-0.2.rc1 then upgraded to the foreman-2.4.0-0.2.rc2.
That’s the only upgrade that was applied.

lzap · March 5, 2021, 4:55pm

Not following, but if you can’t edit it for whatever reason, file an issue please. This needs to work.

2.4.x is not what we call an upgrade, no.