Host not removed from "discovered hosts"

Support
1

Problem:
Upon successful provision of a discovered host, host is created, built and visible in hosts list, but is also still visible (with same hostname) in “discovered hosts”. This is not always reproducible, it happens approx. once every 10-15 times. Please see attached logs during provisioning of host “babaroga0030487e985e”.

Expected outcome:
On provision host should be removed from “discovered hosts”

Foreman and Proxy versions:
1.22
Foreman and Proxy plugin versions:
discovery 15.0

Other relevant data:
foreman production log:

2019-07-29T17:06:20 [I|app|89c294ff] Started GET "/discovered_hosts" for 10.93.0.1 at 2019-07-29 17:06:20 +0200
2019-07-29T17:06:20 [I|app|89c294ff] Processing by DiscoveredHostsController#index as HTML
2019-07-29T17:06:20 [I|app|89c294ff] Current user set to admin (admin)
2019-07-29T17:06:20 [I|app|89c294ff]   Rendering vendor/ruby/2.3.0/gems/foreman_discovery-15.0.0/app/views/discovered_hosts/index.html.erb within layouts/application
2019-07-29T17:06:20 [I|app|89c294ff]   Rendered vendor/ruby/2.3.0/gems/foreman_discovery-15.0.0/app/views/discovered_hosts/_discovered_host.html.erb (3.3ms)
2019-07-29T17:06:20 [I|app|89c294ff]   Rendered vendor/ruby/2.3.0/gems/foreman_discovery-15.0.0/app/views/discovered_hosts/_discovered_host_modal.html.erb (12.2ms)
2019-07-29T17:06:20 [I|app|89c294ff]   Rendered common/_pagination.html.erb (0.4ms)
2019-07-29T17:06:20 [I|app|89c294ff]   Rendered vendor/ruby/2.3.0/gems/foreman_discovery-15.0.0/app/views/discovered_hosts/_discovered_hosts_list.html.erb (23.2ms)
2019-07-29T17:06:20 [I|app|89c294ff]   Rendered vendor/ruby/2.3.0/gems/foreman_discovery-15.0.0/app/views/discovered_hosts/index.html.erb within layouts/application (24.6ms)
2019-07-29T17:06:20 [I|app|89c294ff]   Rendered common/_searchbar.html.erb (0.6ms)
2019-07-29T17:06:20 [I|app|89c294ff]   Rendered layouts/_application_content.html.erb (1.3ms)
2019-07-29T17:06:20 [I|app|89c294ff]   Rendering layouts/base.html.erb
2019-07-29T17:06:20 [I|app|89c294ff]   Rendered layouts/base.html.erb (25.3ms)
2019-07-29T17:06:20 [I|app|89c294ff] Completed 200 OK in 104ms (Views: 50.5ms | ActiveRecord: 11.0ms)
2019-07-29T17:06:21 [I|app|9658e827] Started GET "/notification_recipients" for 10.93.0.1 at 2019-07-29 17:06:21 +0200
2019-07-29T17:06:21 [I|app|9658e827] Processing by NotificationRecipientsController#index as JSON
2019-07-29T17:06:21 [I|app|9658e827] Current user set to admin (admin)
2019-07-29T17:06:21 [I|app|9658e827] Completed 200 OK in 13ms (Views: 0.2ms | ActiveRecord: 1.7ms)
2019-07-29T17:06:26 [I|app|20dfc168] Started GET "/discovered_hosts/babaroga0030487e985e/edit?utf8=%E2%9C%93&host%5Bhostgroup_id%5D=9&host%5Borganization_id%5D=2&host%5Blocation_id%5D=1" for 10.93.0.1 at 2019-07-29 17:06:26 +0200
2019-07-29T17:06:26 [I|app|20dfc168] Processing by DiscoveredHostsController#edit as HTML
2019-07-29T17:06:26 [I|app|20dfc168]   Parameters: {"utf8"=>"✓", "host"=>{"hostgroup_id"=>"9", "organization_id"=>"2", "location_id"=>"1"}, "id"=>"babaroga0030487e985e"}
2019-07-29T17:06:26 [I|app|20dfc168] Current user set to admin (admin)
2019-07-29T17:06:26 [I|app|20dfc168]   Rendering vendor/ruby/2.3.0/gems/foreman_discovery-15.0.0/app/views/discovered_hosts/edit.html.erb within layouts/application
2019-07-29T17:06:26 [I|app|20dfc168]   Rendered hosts/_progress.html.erb (0.2ms)
2019-07-29T17:06:26 [I|app|20dfc168]   Rendered hosts/puppet/_main_tab_fields.html.erb (5.9ms)
2019-07-29T17:06:26 [I|app|20dfc168]   Rendered collection of puppetclasses/_selectedClasses.html.erb [0 times] (0.0ms)
2019-07-29T17:06:26 [I|app|20dfc168]   Rendered collection of puppetclasses/_classes_in_groups.html.erb [0 times] (0.0ms)
2019-07-29T17:06:26 [I|app|20dfc168]   Rendered puppetclasses/_classes.html.erb (0.1ms)
2019-07-29T17:06:26 [I|app|20dfc168]   Rendered puppetclasses/_class_selection.html.erb (76.7ms)
2019-07-29T17:06:26 [I|app|20dfc168]   Rendered hosts/puppet/_puppet_classes_tab.html.erb (77.0ms)
2019-07-29T17:06:26 [I|app|20dfc168]   Rendered nic/_base_form.html.erb (66.8ms)
2019-07-29T17:06:26 [I|app|20dfc168]   Rendered nic/_virtual_form.html.erb (1.8ms)
2019-07-29T17:06:26 [I|app|20dfc168]   Rendered nic/_provider_specific_form.html.erb (0.1ms)
2019-07-29T17:06:26 [I|app|20dfc168]   Rendered nic/manageds/_managed.html.erb (70.5ms)
2019-07-29T17:06:26 [I|app|20dfc168]   Rendered nic/_base_form.html.erb (61.2ms)
2019-07-29T17:06:26 [I|app|20dfc168]   Rendered nic/_virtual_form.html.erb (1.8ms)
2019-07-29T17:06:26 [I|app|20dfc168]   Rendered nic/_provider_specific_form.html.erb (0.1ms)
2019-07-29T17:06:26 [I|app|20dfc168]   Rendered nic/manageds/_managed.html.erb (64.8ms)
2019-07-29T17:06:26 [I|app|20dfc168]   Rendered nic/_base_form.html.erb (61.7ms)
2019-07-29T17:06:26 [I|app|20dfc168]   Rendered nic/_provider_specific_form.html.erb (0.1ms)
2019-07-29T17:06:26 [I|app|20dfc168]   Rendered nic/bmcs/_bmc.html.erb (65.6ms)
2019-07-29T17:06:26 [I|app|20dfc168]   Rendered nic/_base_form.html.erb (63.3ms)
2019-07-29T17:06:27 [I|app|20dfc168]   Rendered nic/_virtual_form.html.erb (1.7ms)
2019-07-29T17:06:27 [I|app|20dfc168]   Rendered nic/_provider_specific_form.html.erb (0.1ms)
2019-07-29T17:06:27 [I|app|20dfc168]   Rendered nic/manageds/_managed.html.erb (66.9ms)
2019-07-29T17:06:27 [I|app|20dfc168]   Rendered hosts/_interfaces.html.erb (271.2ms)
2019-07-29T17:06:27 [I|app|20dfc168]   Rendered common/os_selection/_architecture.html.erb (8.2ms)
2019-07-29T17:06:27 [I|app|20dfc168]   Rendered common/os_selection/_pxe_loader.html.erb (5.7ms)
2019-07-29T17:06:27 [I|app|20dfc168]   Rendered common/os_selection/_operatingsystem.html.erb (38.5ms)
2019-07-29T17:06:27 [I|app|20dfc168]   Rendered hosts/provision_method/build/_form.html.erb (40.5ms)
2019-07-29T17:06:27 [I|app|20dfc168]   Rendered hosts/provision_method/image/_form.html.erb (0.1ms)
2019-07-29T17:06:27 [I|app|20dfc168]   Rendered hosts/_operating_system.html.erb (56.0ms)
2019-07-29T17:06:27 [I|app|20dfc168]   Rendered hosts/_unattended.html.erb (56.3ms)
2019-07-29T17:06:27 [I|app|20dfc168]   Rendered collection of puppetclasses/_class_parameters.html.erb [0 times] (0.0ms)
2019-07-29T17:06:27 [I|app|20dfc168]   Rendered puppetclasses/_classes_parameters.html.erb (16.1ms)
2019-07-29T17:06:27 [I|app|20dfc168]   Rendered common_parameters/_inherited_parameters.html.erb (4.5ms)
2019-07-29T17:06:27 [I|app|20dfc168]   Rendered common_parameters/_parameter.html.erb (2.5ms)
2019-07-29T17:06:27 [I|app|20dfc168]   Rendered common_parameters/_parameters.html.erb (5.2ms)
2019-07-29T17:06:27 [I|app|20dfc168]   Rendered hosts/_form.html.erb (540.9ms)
2019-07-29T17:06:27 [I|app|20dfc168]   Rendered vendor/ruby/2.3.0/gems/foreman_discovery-15.0.0/app/views/discovered_hosts/edit.html.erb within layouts/application (541.4ms)
2019-07-29T17:06:27 [W|app|20dfc168] unable to detect breadcrumb title name in for discovered_hosts, defaulting to name
2019-07-29T17:06:27 [I|app|20dfc168]   Rendered layouts/_application_content.html.erb (2.1ms)
2019-07-29T17:06:27 [I|app|20dfc168]   Rendering layouts/base.html.erb
2019-07-29T17:06:27 [I|app|20dfc168]   Rendered layouts/base.html.erb (25.8ms)
2019-07-29T17:06:27 [I|app|20dfc168] Completed 200 OK in 768ms (Views: 528.2ms | ActiveRecord: 69.5ms)
2019-07-29T17:06:27 [I|app|5e84f477] Started GET "/notification_recipients" for 10.93.0.1 at 2019-07-29 17:06:27 +0200
2019-07-29T17:06:27 [I|app|5e84f477] Processing by NotificationRecipientsController#index as JSON
2019-07-29T17:06:27 [I|app|5e84f477] Current user set to admin (admin)
2019-07-29T17:06:27 [I|app|5e84f477] Completed 200 OK in 14ms (Views: 0.2ms | ActiveRecord: 1.7ms)
2019-07-29T17:06:38 [I|app|8f9a79d8] Started GET "/notification_recipients" for 10.93.0.1 at 2019-07-29 17:06:38 +0200
2019-07-29T17:06:38 [I|app|8f9a79d8] Processing by NotificationRecipientsController#index as JSON
2019-07-29T17:06:38 [I|app|8f9a79d8] Current user set to admin (admin)
2019-07-29T17:06:38 [I|app|8f9a79d8] Completed 200 OK in 12ms (Views: 0.2ms | ActiveRecord: 1.7ms)
2019-07-29T17:06:48 [I|app|bf02f2bc] Started GET "/notification_recipients" for 10.93.0.1 at 2019-07-29 17:06:48 +0200
2019-07-29T17:06:48 [I|app|bf02f2bc] Processing by NotificationRecipientsController#index as JSON
2019-07-29T17:06:48 [I|app|bf02f2bc] Current user set to admin (admin)
2019-07-29T17:06:48 [I|app|bf02f2bc] Completed 200 OK in 12ms (Views: 0.2ms | ActiveRecord: 1.8ms)
2019-07-29T17:06:52 [I|app|ea72d063] Started PATCH "/discovered_hosts/152" for 10.93.0.1 at 2019-07-29 17:06:52 +0200
2019-07-29T17:06:52 [I|app|ea72d063] Processing by DiscoveredHostsController#update as */*
2019-07-29T17:06:52 [I|app|ea72d063]   Parameters: {"utf8"=>"✓", "authenticity_token"=>"KyGT+XTnmenMfGjyUygJGv6zuDuNgAa1c1yXzL1b4sCe/BOPBfBx69OMLv2twff5lXDpQbD2DPe2QHAWipKZVQ==", "host"=>{"name"=>"babaroga0030487e985e", "organization_id"=>"2", "location_id"=>"1", "hostgroup_id"=>"9", "puppetclass_ids"=>[""], "managed"=>"true", "progress_report_id"=>"[FILTERED]", "type"=>"Host::Managed", "interfaces_attributes"=>{"0"=>{"_destroy"=>"0", "mac"=>"00:30:48:7e:98:5e", "identifier"=>"enp4s0f0", "name"=>"babaroga0030487e985e", "domain_id"=>"1", "subnet_id"=>"1", "ip"=>"10.137.111.152", "ip6"=>"", "managed"=>"1", "primary"=>"1", "provision"=>"1", "tag"=>"", "attached_to"=>"", "id"=>"352"}, "1"=>{"_destroy"=>"0", "mac"=>"00:30:48:7e:98:5f", "identifier"=>"enp4s0f1", "name"=>"", "domain_id"=>"", "subnet_id"=>"", "ip"=>"", "ip6"=>"", "managed"=>"0", "primary"=>"0", "provision"=>"0", "tag"=>"", "attached_to"=>"", "id"=>"353"}, "2"=>{"_destroy"=>"0", "mac"=>"00:30:48:d8:ed:30", "identifier"=>"ipmi", "name"=>"", "domain_id"=>"", "subnet_id"=>"", "ip"=>"10.137.101.201", "ip6"=>"", "managed"=>"0", "primary"=>"0", "provision"=>"0", "username"=>"ADMIN", "password"=>"[FILTERED]", "provider"=>"IPMI", "id"=>"354"}}, "architecture_id"=>"1", "operatingsystem_id"=>"1", "build"=>"1", "medium_id"=>"2", "ptable_id"=>"115", "pxe_loader"=>"PXELinux BIOS", "disk"=>"", "is_owned_by"=>"", "enabled"=>"1", "model_id"=>"2", "comment"=>"", "overwrite"=>"false"}, "fakepassword"=>"[FILTERED]", "id"=>"152"}
2019-07-29T17:06:52 [I|app|ea72d063] Current user set to admin (admin)
2019-07-29T17:06:53 [I|app|ea72d063] Create DHCP reservation babaroga0030487e985e.babaroga2.local for babaroga0030487e985e.babaroga2.local-00:30:48:7e:98:5e/10.137.111.152
2019-07-29T17:06:53 [I|app|ea72d063] Add DNS A record for babaroga0030487e985e.babaroga2.local/10.137.111.152
2019-07-29T17:06:53 [I|app|ea72d063] Add DNS PTR record for 10.137.111.152/babaroga0030487e985e.babaroga2.local
2019-07-29T17:06:54 [I|app|ea72d063] Deploying TFTP PXELinux configuration for babaroga0030487e985e.babaroga2.local
2019-07-29T17:06:54 [I|app|ea72d063] Skipping TFTP PXEGrub2 configuration for babaroga0030487e985e.babaroga2.local
2019-07-29T17:06:54 [I|app|ea72d063] Skipping TFTP PXEGrub configuration for babaroga0030487e985e.babaroga2.local
2019-07-29T17:06:54 [I|app|ea72d063] Deploying TFTP iPXE configuration for babaroga0030487e985e.babaroga2.local
2019-07-29T17:06:54 [I|app|ea72d063] Fetching required TFTP boot files for babaroga0030487e985e.babaroga2.local
2019-07-29T17:06:54 [I|app|03cc1238] Started GET "/tasks/24c1c21e-a7eb-4acd-b607-d7a11e7609ef" for 10.93.0.1 at 2019-07-29 17:06:54 +0200
2019-07-29T17:06:54 [I|app|03cc1238] Processing by TasksController#show as */*
2019-07-29T17:06:54 [I|app|03cc1238]   Parameters: {"id"=>"24c1c21e-a7eb-4acd-b607-d7a11e7609ef"}
2019-07-29T17:06:54 [I|app|03cc1238] Current user set to admin (admin)
2019-07-29T17:06:54 [I|app|03cc1238]   Rendered tasks/_list.html.erb (1.3ms)
2019-07-29T17:06:54 [I|app|03cc1238] Completed 200 OK in 18ms (Views: 8.3ms | ActiveRecord: 1.7ms)
2019-07-29T17:06:54 [I|app|ea72d063] Processed 8 tasks from queue 'Host::Managed Main', completed 8/8
2019-07-29T17:06:54 [I|aud|ea72d063] Host::Base (152) update event on name babaroga0030487e985e, babaroga0030487e985e.babaroga2.local
2019-07-29T17:06:54 [I|aud|ea72d063] Host::Base (152) update event on root_pass , $5$YArpOWgmRPs7zR5M$4Fc4NcltHXFFKLon8iGxVj33KUuyIl6BAGO7Ub2mm32
2019-07-29T17:06:54 [I|aud|ea72d063] Host::Base (152) update event on architecture_id , 1
2019-07-29T17:06:54 [I|aud|ea72d063] Host::Base (152) update event on operatingsystem_id , 1
2019-07-29T17:06:54 [I|aud|ea72d063] Host::Base (152) update event on environment_id , 1
2019-07-29T17:06:54 [I|aud|ea72d063] Host::Base (152) update event on ptable_id , 115
2019-07-29T17:06:54 [I|aud|ea72d063] Host::Base (152) update event on medium_id , 2
2019-07-29T17:06:54 [I|aud|ea72d063] Host::Base (152) update event on build false, true
2019-07-29T17:06:54 [I|aud|ea72d063] Host::Base (152) update event on comment , 
2019-07-29T17:06:54 [I|aud|ea72d063] Host::Base (152) update event on disk , 
2019-07-29T17:06:54 [I|aud|ea72d063] Host::Base (152) update event on hostgroup_id , 9
2019-07-29T17:06:54 [I|aud|ea72d063] Host::Base (152) update event on owner_id 1, 4
2019-07-29T17:06:54 [I|aud|ea72d063] Host::Base (152) update event on managed false, true
2019-07-29T17:06:54 [I|aud|ea72d063] Host::Base (152) update event on grub_pass , $5$YArpOWgmRPs7zR5M$4Fc4NcltHXFFKLon8iGxVj33KUuyIl6BAGO7Ub2mm32
2019-07-29T17:06:54 [I|aud|ea72d063] Host::Base (152) update event on pxe_loader , PXELinux BIOS
2019-07-29T17:06:54 [I|aud|ea72d063] Nic::Managed (352) update event on name babaroga0030487e985e, babaroga0030487e985e.babaroga2.local
2019-07-29T17:06:54 [I|aud|ea72d063] Nic::Managed (352) update event on domain_id , 1
2019-07-29T17:06:54 [I|aud|ea72d063] Nic::Managed (352) update event on ip6 , 
2019-07-29T17:06:54 [I|aud|ea72d063] Nic::Managed (353) update event on name , 
2019-07-29T17:06:54 [I|aud|ea72d063] Nic::Managed (353) update event on ip6 , 
2019-07-29T17:06:54 [I|aud|ea72d063] Nic::BMC (354) update event on name , 
2019-07-29T17:06:54 [I|aud|ea72d063] Nic::BMC (354) update event on username , ADMIN
2019-07-29T17:06:54 [I|aud|ea72d063] Nic::BMC (354) update event on password [redacted], [redacted]
2019-07-29T17:06:54 [I|aud|ea72d063] Nic::BMC (354) update event on ip6 , 
2019-07-29T17:06:54 [I|app|ea72d063] Processed 1 tasks from queue 'Host::Managed Post', completed 1/1
2019-07-29T17:06:54 [I|app|ea72d063] Redirected to https://10.137.100.20/hosts/babaroga0030487e985e.babaroga2.local
2019-07-29T17:06:54 [I|app|ea72d063] Completed 302 Found in 2015ms (ActiveRecord: 116.7ms)
2019-07-29T17:06:54 [I|app|69d9a7c4] Started GET "/hosts/babaroga0030487e985e.babaroga2.local" for 10.93.0.1 at 2019-07-29 17:06:54 +0200
2019-07-29T17:06:54 [I|app|69d9a7c4] Processing by HostsController#show as */*
2019-07-29T17:06:54 [I|app|69d9a7c4]   Parameters: {"id"=>"babaroga0030487e985e.babaroga2.local"}
2019-07-29T17:06:54 [I|app|69d9a7c4] Current user set to admin (admin)
2019-07-29T17:06:54 [I|app|69d9a7c4]   Rendering hosts/show.html.erb within layouts/application
2019-07-29T17:06:54 [I|app|69d9a7c4]   Rendered hosts/show.html.erb within layouts/application (24.6ms)
2019-07-29T17:06:54 [I|app|69d9a7c4]   Rendered layouts/_application_content.html.erb (0.5ms)
2019-07-29T17:06:54 [I|app|69d9a7c4]   Rendering layouts/base.html.erb
2019-07-29T17:06:54 [I|app|69d9a7c4]   Rendered layouts/base.html.erb (26.5ms)
2019-07-29T17:06:54 [I|app|69d9a7c4] Completed 200 OK in 78ms (Views: 49.1ms | ActiveRecord: 8.7ms)
2019-07-29T17:06:55 [I|app|ba2ff443] Started GET "/hosts/babaroga0030487e985e.babaroga2.local/overview" for 10.93.0.1 at 2019-07-29 17:06:55 +0200
2019-07-29T17:06:55 [I|app|ba2ff443] Processing by HostsController#overview as HTML
2019-07-29T17:06:55 [I|app|ba2ff443]   Parameters: {"id"=>"babaroga0030487e985e.babaroga2.local"}
2019-07-29T17:06:55 [I|app|b2604c26] Started GET "/hosts/babaroga0030487e985e.babaroga2.local/templates" for 10.93.0.1 at 2019-07-29 17:06:55 +0200
2019-07-29T17:06:55 [I|app|ba2ff443] Current user set to admin (admin)
2019-07-29T17:06:55 [I|app|b2604c26] Processing by HostsController#templates as HTML
2019-07-29T17:06:55 [I|app|b2604c26]   Parameters: {"id"=>"babaroga0030487e985e.babaroga2.local"}
2019-07-29T17:06:55 [I|app|6481266d] Started GET "/hosts/babaroga0030487e985e.babaroga2.local/nics" for 10.93.0.1 at 2019-07-29 17:06:55 +0200
2019-07-29T17:06:55 [I|app|b2604c26] Current user set to admin (admin)
2019-07-29T17:06:55 [I|app|ba2ff443]   Rendered hosts/_overview.html.erb (52.5ms)
2019-07-29T17:06:55 [I|app|ba2ff443] Completed 200 OK in 90ms (Views: 45.0ms | ActiveRecord: 21.0ms)
2019-07-29T17:06:55 [I|app|deeb470e] Started GET "/hosts/babaroga0030487e985e.babaroga2.local/bmc" for 10.93.0.1 at 2019-07-29 17:06:55 +0200
2019-07-29T17:06:55 [I|app|deeb470e] Processing by HostsController#bmc as HTML
2019-07-29T17:06:55 [I|app|deeb470e]   Parameters: {"id"=>"babaroga0030487e985e.babaroga2.local"}
2019-07-29T17:06:55 [I|app|deeb470e] Current user set to admin (admin)
2019-07-29T17:06:55 [I|app|6481266d] Processing by HostsController#nics as HTML
2019-07-29T17:06:55 [I|app|6481266d]   Parameters: {"id"=>"babaroga0030487e985e.babaroga2.local"}
2019-07-29T17:06:55 [I|app|6481266d] Current user set to admin (admin)
2019-07-29T17:06:55 [I|app|b2604c26]   Rendered hosts/_templates.html.erb (43.8ms)
2019-07-29T17:06:55 [I|app|b2604c26] Completed 200 OK in 359ms (Views: 50.3ms | ActiveRecord: 82.0ms)
2019-07-29T17:06:55 [I|app|e9364b92] Started GET "/hosts/babaroga0030487e985e.babaroga2.local/resources?range=7" for 10.93.0.1 at 2019-07-29 17:06:55 +0200
2019-07-29T17:06:55 [I|app|e9364b92] Processing by HostsController#resources as HTML
2019-07-29T17:06:55 [I|app|e9364b92]   Parameters: {"range"=>"7", "id"=>"babaroga0030487e985e.babaroga2.local"}
2019-07-29T17:06:55 [I|app|e9364b92] Current user set to admin (admin)
2019-07-29T17:06:55 [I|app|e9364b92]   Rendered hosts/_resources.html.erb (4.8ms)
2019-07-29T17:06:55 [I|app|e9364b92] Completed 200 OK in 30ms (Views: 5.4ms | ActiveRecord: 5.0ms)
2019-07-29T17:06:55 [I|app|33557f94] Started GET "/hosts/babaroga0030487e985e.babaroga2.local/runtime?range=7" for 10.93.0.1 at 2019-07-29 17:06:55 +0200
2019-07-29T17:06:55 [I|app|33557f94] Processing by HostsController#runtime as HTML
2019-07-29T17:06:55 [I|app|33557f94]   Parameters: {"range"=>"7", "id"=>"babaroga0030487e985e.babaroga2.local"}
2019-07-29T17:06:55 [I|app|33557f94] Current user set to admin (admin)
2019-07-29T17:06:55 [I|app|33557f94]   Rendered hosts/_runtime.html.erb (4.3ms)
2019-07-29T17:06:55 [I|app|33557f94] Completed 200 OK in 35ms (Views: 10.6ms | ActiveRecord: 4.3ms)
2019-07-29T17:06:56 [I|app|6481266d]   Rendered hosts/_nics.html.erb (388.9ms)
2019-07-29T17:06:56 [I|app|6481266d] Completed 200 OK in 835ms (Views: 380.8ms | ActiveRecord: 38.7ms)
2019-07-29T17:06:56 [I|app|deeb470e]   Rendered hosts/_bmc.html.erb (1408.8ms)
2019-07-29T17:06:56 [I|app|deeb470e] Completed 200 OK in 1432ms (Views: 1408.5ms | ActiveRecord: 5.8ms)
2019-07-29T17:06:57 [I|app|28978f38] Started POST "/api/v2/discovered_hosts/facts" for 10.137.100.121 at 2019-07-29 17:06:57 +0200
2019-07-29T17:06:57 [I|app|28978f38] Processing by Api::V2::DiscoveredHostsController#facts as JSON
2019-07-29T17:06:57 [I|app|28978f38]   Parameters: {"facts"=>"[FILTERED]", "apiv"=>"v2", "discovered_host"=>{"facts"=>"[FILTERED]"}}
2019-07-29T17:06:57 [W|app|28978f38] One or more existing managed hosts found: babaroga0030487e985e.babaroga2.local/00:30:48:7e:98:5e
2019-07-29T17:06:57 [I|aud|28978f38] Nic::Managed (355) create event on mac 
2019-07-29T17:06:57 [I|aud|28978f38] Nic::Managed (355) create event on ip 
2019-07-29T17:06:57 [I|aud|28978f38] Nic::Managed (355) create event on type Nic::Managed
2019-07-29T17:06:57 [I|aud|28978f38] Nic::Managed (355) create event on name babaroga0030487e985e
2019-07-29T17:06:57 [I|aud|28978f38] Nic::Managed (355) create event on host_id 153
2019-07-29T17:06:57 [I|aud|28978f38] Nic::Managed (355) create event on subnet_id 
2019-07-29T17:06:57 [I|aud|28978f38] Nic::Managed (355) create event on domain_id 
2019-07-29T17:06:57 [I|aud|28978f38] Nic::Managed (355) create event on attrs {}
2019-07-29T17:06:57 [I|aud|28978f38] Nic::Managed (355) create event on provider 
2019-07-29T17:06:57 [I|aud|28978f38] Nic::Managed (355) create event on username 
2019-07-29T17:06:57 [I|aud|28978f38] Nic::Managed (355) create event on password [redacted]
2019-07-29T17:06:57 [I|aud|28978f38] Nic::Managed (355) create event on virtual false
2019-07-29T17:06:57 [I|aud|28978f38] Nic::Managed (355) create event on link true
2019-07-29T17:06:57 [I|aud|28978f38] Nic::Managed (355) create event on identifier 
2019-07-29T17:06:57 [I|aud|28978f38] Nic::Managed (355) create event on tag 
2019-07-29T17:06:57 [I|aud|28978f38] Nic::Managed (355) create event on attached_to 
2019-07-29T17:06:57 [I|aud|28978f38] Nic::Managed (355) create event on managed true
2019-07-29T17:06:57 [I|aud|28978f38] Nic::Managed (355) create event on mode balance-rr
2019-07-29T17:06:57 [I|aud|28978f38] Nic::Managed (355) create event on attached_devices 
2019-07-29T17:06:57 [I|aud|28978f38] Nic::Managed (355) create event on bond_options 
2019-07-29T17:06:57 [I|aud|28978f38] Nic::Managed (355) create event on primary true
2019-07-29T17:06:57 [I|aud|28978f38] Nic::Managed (355) create event on provision true
2019-07-29T17:06:57 [I|aud|28978f38] Nic::Managed (355) create event on compute_attributes {}
2019-07-29T17:06:57 [I|aud|28978f38] Nic::Managed (355) create event on ip6 
2019-07-29T17:06:57 [I|aud|28978f38] Nic::Managed (355) create event on subnet6_id 
2019-07-29T17:06:57 [I|aud|28978f38] Host::Base (153) create event on name babaroga0030487e985e
2019-07-29T17:06:57 [I|aud|28978f38] Host::Base (153) create event on last_compile 
2019-07-29T17:06:57 [I|aud|28978f38] Host::Base (153) create event on root_pass 
2019-07-29T17:06:57 [I|aud|28978f38] Host::Base (153) create event on architecture_id 
2019-07-29T17:06:57 [I|aud|28978f38] Host::Base (153) create event on operatingsystem_id 
2019-07-29T17:06:57 [I|aud|28978f38] Host::Base (153) create event on environment_id 
2019-07-29T17:06:57 [I|aud|28978f38] Host::Base (153) create event on ptable_id 
2019-07-29T17:06:57 [I|aud|28978f38] Host::Base (153) create event on medium_id 
2019-07-29T17:06:57 [I|aud|28978f38] Host::Base (153) create event on build false
2019-07-29T17:06:57 [I|aud|28978f38] Host::Base (153) create event on comment 
2019-07-29T17:06:57 [I|aud|28978f38] Host::Base (153) create event on disk 
2019-07-29T17:06:57 [I|aud|28978f38] Host::Base (153) create event on installed_at 
2019-07-29T17:06:57 [I|aud|28978f38] Host::Base (153) create event on model_id 
2019-07-29T17:06:57 [I|aud|28978f38] Host::Base (153) create event on hostgroup_id 
2019-07-29T17:06:57 [I|aud|28978f38] Host::Base (153) create event on owner_id 
2019-07-29T17:06:57 [I|aud|28978f38] Host::Base (153) create event on owner_type 
2019-07-29T17:06:57 [I|aud|28978f38] Host::Base (153) create event on enabled true
2019-07-29T17:06:57 [I|aud|28978f38] Host::Base (153) create event on puppet_ca_proxy_id 
2019-07-29T17:06:57 [I|aud|28978f38] Host::Base (153) create event on managed false
2019-07-29T17:06:57 [I|aud|28978f38] Host::Base (153) create event on use_image 
2019-07-29T17:06:57 [I|aud|28978f38] Host::Base (153) create event on image_file 
2019-07-29T17:06:57 [I|aud|28978f38] Host::Base (153) create event on uuid 
2019-07-29T17:06:57 [I|aud|28978f38] Host::Base (153) create event on compute_resource_id 
2019-07-29T17:06:57 [I|aud|28978f38] Host::Base (153) create event on puppet_proxy_id 
2019-07-29T17:06:57 [I|aud|28978f38] Host::Base (153) create event on certname 
2019-07-29T17:06:57 [I|aud|28978f38] Host::Base (153) create event on image_id 
2019-07-29T17:06:57 [I|aud|28978f38] Host::Base (153) create event on organization_id 
2019-07-29T17:06:57 [I|aud|28978f38] Host::Base (153) create event on location_id 
2019-07-29T17:06:57 [I|aud|28978f38] Host::Base (153) create event on otp 
2019-07-29T17:06:57 [I|aud|28978f38] Host::Base (153) create event on realm_id 
2019-07-29T17:06:57 [I|aud|28978f38] Host::Base (153) create event on compute_profile_id 
2019-07-29T17:06:57 [I|aud|28978f38] Host::Base (153) create event on provision_method 
2019-07-29T17:06:57 [I|aud|28978f38] Host::Base (153) create event on grub_pass 
2019-07-29T17:06:57 [I|aud|28978f38] Host::Base (153) create event on global_status 0
2019-07-29T17:06:57 [I|aud|28978f38] Host::Base (153) create event on lookup_value_matcher 
2019-07-29T17:06:57 [I|aud|28978f38] Host::Base (153) create event on pxe_loader 
2019-07-29T17:06:57 [I|aud|28978f38] Host::Base (153) create event on initiated_at 
2019-07-29T17:06:57 [I|aud|28978f38] Host::Base (153) create event on build_errors 
2019-07-29T17:06:57 [I|aud|28978f38] Host::Base (153) create event on discovery_rule_id 
2019-07-29T17:06:59 [I|app|28978f38] Import facts for 'babaroga0030487e985e' completed. Added: 215, Updated: 0, Deleted 0 facts
2019-07-29T17:06:59 [I|aud|28978f38] Nic::Managed (355) update event on mac , 00:30:48:7e:98:5e
2019-07-29T17:06:59 [I|aud|28978f38] Nic::Managed (355) update event on identifier , enp4s0f0
2019-07-29T17:06:59 [I|app|28978f38] Detected subnet: babaroga2 with taxonomy ["Default Organization"]/["Default Location"]
2019-07-29T17:06:59 [I|app|28978f38] Assigned location: Default Location
2019-07-29T17:06:59 [I|app|28978f38] Assigned organization: Default Organization
2019-07-29T17:06:59 [I|aud|28978f38] Host::Base (153) update event on model_id , 2
2019-07-29T17:06:59 [I|aud|28978f38] Host::Base (153) update event on owner_id , 1
2019-07-29T17:06:59 [I|aud|28978f38] Host::Base (153) update event on owner_type , User
2019-07-29T17:06:59 [I|aud|28978f38] Host::Base (153) update event on organization_id , 2
2019-07-29T17:06:59 [I|aud|28978f38] Host::Base (153) update event on location_id , 1
2019-07-29T17:06:59 [I|aud|28978f38] Nic::Managed (355) update event on subnet_id , 1
2019-07-29T17:06:59 [I|app|28978f38] Completed 201 Created in 1777ms (Views: 2.2ms | ActiveRecord: 477.1ms)
2019-07-29T17:08:24 [I|app|cc511bdc] Started GET "/unattended/provision?token=890d02f0-3361-4bc1-bb8b-983eba999283&url=http%3A%2F%2Fforeman-2-proxy-1.babaroga2.local%3A8000" for foreman-2-proxy-1.babaroga2.local at 2019-07-29 17:08:24 +0200
2019-07-29T17:08:24 [I|app|cc511bdc] Processing by UnattendedController#host_template as TEXT
2019-07-29T17:08:24 [I|app|cc511bdc]   Parameters: {"token"=>"890d02f0-3361-4bc1-bb8b-983eba999283", "url"=>"http://foreman-2-proxy-1.babaroga2.local:8000", "kind"=>"provision", "unattended"=>{}}
2019-07-29T17:08:24 [I|app|cc511bdc]   Rendering text template
2019-07-29T17:08:24 [I|app|cc511bdc]   Rendered text template (0.0ms)
2019-07-29T17:08:24 [I|app|cc511bdc] Completed 200 OK in 221ms (Views: 0.8ms | ActiveRecord: 30.4ms)
2019-07-29T17:08:58 [I|app|3b82ab2c] Started GET "/notification_recipients" for 10.93.0.1 at 2019-07-29 17:08:58 +0200
2019-07-29T17:08:58 [I|app|3b82ab2c] Processing by NotificationRecipientsController#index as JSON
2019-07-29T17:08:58 [I|app|3b82ab2c] Current user set to admin (admin)
2019-07-29T17:08:58 [I|app|3b82ab2c] Completed 200 OK in 26ms (Views: 0.2ms | ActiveRecord: 4.5ms)
2019-07-29T17:09:09 [I|app|6793eff7] Started GET "/notification_recipients" for 10.93.0.1 at 2019-07-29 17:09:09 +0200
2019-07-29T17:09:09 [I|app|6793eff7] Processing by NotificationRecipientsController#index as JSON
2019-07-29T17:09:09 [I|app|6793eff7] Current user set to admin (admin)
2019-07-29T17:09:09 [I|app|6793eff7] Completed 200 OK in 12ms (Views: 0.2ms | ActiveRecord: 1.7ms)
2019-07-29T17:09:13 [I|app|98558473] Started GET "/hostgroups" for 10.93.0.1 at 2019-07-29 17:09:13 +0200
2019-07-29T17:09:13 [I|app|98558473] Processing by HostgroupsController#index as HTML
2019-07-29T17:09:13 [I|app|98558473] Current user set to admin (admin)
2019-07-29T17:09:13 [I|app|98558473]   Rendering hostgroups/index.html.erb within layouts/application
2019-07-29T17:09:13 [I|app|98558473]   Rendered common/_pagination.html.erb (0.5ms)
2019-07-29T17:09:13 [I|app|98558473]   Rendered hostgroups/index.html.erb within layouts/application (79.5ms)
2019-07-29T17:09:13 [I|app|98558473]   Rendered common/_searchbar.html.erb (0.6ms)
2019-07-29T17:09:13 [I|app|98558473]   Rendered layouts/_application_content.html.erb (1.5ms)
2019-07-29T17:09:13 [I|app|98558473]   Rendering layouts/base.html.erb
2019-07-29T17:09:13 [I|app|98558473]   Rendered layouts/base.html.erb (28.5ms)
2019-07-29T17:09:13 [I|app|98558473] Completed 200 OK in 133ms (Views: 100.2ms | ActiveRecord: 14.5ms)
2019-07-29T17:09:19 [I|app|f7e6fb0f] Started GET "/notification_recipients" for 10.93.0.1 at 2019-07-29 17:09:19 +0200
2019-07-29T17:09:19 [I|app|f7e6fb0f] Processing by NotificationRecipientsController#index as JSON
2019-07-29T17:09:19 [I|app|f7e6fb0f] Current user set to admin (admin)
2019-07-29T17:09:19 [I|app|f7e6fb0f] Completed 200 OK in 14ms (Views: 0.2ms | ActiveRecord: 1.8ms)
2019-07-29T17:09:24 [I|app|ec85c833] Started GET "/hostgroups/9-babaroga2-test1-babaroga2-test1-debian-2disk-raid1-lvm-gpt/edit" for 10.93.0.1 at 2019-07-29 17:09:24 +0200
2019-07-29T17:09:24 [I|app|ec85c833] Processing by HostgroupsController#edit as HTML
2019-07-29T17:09:24 [I|app|ec85c833]   Parameters: {"id"=>"9-babaroga2-test1-babaroga2-test1-debian-2disk-raid1-lvm-gpt"}
2019-07-29T17:09:24 [I|app|ec85c833] Current user set to admin (admin)
2019-07-29T17:09:24 [I|app|ec85c833]   Rendering hostgroups/edit.html.erb within layouts/application
2019-07-29T17:09:25 [I|app|ec85c833]   Rendered collection of puppetclasses/_selectedClasses.html.erb [0 times] (0.0ms)
2019-07-29T17:09:25 [I|app|ec85c833]   Rendered collection of puppetclasses/_classes_in_groups.html.erb [0 times] (0.0ms)
2019-07-29T17:09:25 [I|app|ec85c833]   Rendered puppetclasses/_classes.html.erb (0.1ms)
2019-07-29T17:09:25 [I|app|ec85c833]   Rendered puppetclasses/_class_selection.html.erb (136.6ms)
2019-07-29T17:09:25 [I|app|ec85c833]   Rendered common/os_selection/_architecture.html.erb (8.6ms)
2019-07-29T17:09:25 [I|app|ec85c833]   Rendered common/os_selection/_pxe_loader.html.erb (5.2ms)
2019-07-29T17:09:25 [I|app|ec85c833]   Rendered common/os_selection/_operatingsystem.html.erb (44.3ms)
2019-07-29T17:09:25 [I|app|ec85c833]   Rendered common/os_selection/_initial.html.erb (62.6ms)
2019-07-29T17:09:25 [I|app|ec85c833]   Rendered collection of puppetclasses/_class_parameters.html.erb [0 times] (0.0ms)
2019-07-29T17:09:25 [I|app|ec85c833]   Rendered puppetclasses/_classes_parameters.html.erb (21.5ms)
2019-07-29T17:09:25 [I|app|ec85c833]   Rendered common_parameters/_inherited_parameters.html.erb (3.9ms)
2019-07-29T17:09:25 [I|app|ec85c833]   Rendered common_parameters/_parameter.html.erb (2.4ms)
2019-07-29T17:09:25 [I|app|ec85c833]   Rendered common_parameters/_parameter.html.erb (2.0ms)
2019-07-29T17:09:25 [I|app|ec85c833]   Rendered common_parameters/_parameter.html.erb (2.0ms)
2019-07-29T17:09:25 [I|app|ec85c833]   Rendered common_parameters/_parameter.html.erb (1.8ms)
2019-07-29T17:09:25 [I|app|ec85c833]   Rendered common_parameters/_parameters.html.erb (12.5ms)
2019-07-29T17:09:25 [I|app|ec85c833]   Rendered taxonomies/_loc_org_tabs.html.erb (45.4ms)
2019-07-29T17:09:25 [I|app|ec85c833]   Rendered hostgroups/_form.html.erb (463.6ms)
2019-07-29T17:09:25 [I|app|ec85c833]   Rendered hostgroups/edit.html.erb within layouts/application (464.0ms)
2019-07-29T17:09:25 [I|app|ec85c833]   Rendered layouts/_application_content.html.erb (1.7ms)
2019-07-29T17:09:25 [I|app|ec85c833]   Rendering layouts/base.html.erb
2019-07-29T17:09:25 [I|app|ec85c833]   Rendered layouts/base.html.erb (26.5ms)
2019-07-29T17:09:25 [I|app|ec85c833] Completed 200 OK in 558ms (Views: 441.8ms | ActiveRecord: 66.3ms)
2019-07-29T17:09:25 [I|app|c0156a62] Started GET "/hostgroups/9-babaroga2-test1-babaroga2-test1-debian-2disk-raid1-lvm-gpt/edit" for 10.93.0.1 at 2019-07-29 17:09:25 +0200
2019-07-29T17:09:25 [I|app|c0156a62] Processing by HostgroupsController#edit as HTML
2019-07-29T17:09:25 [I|app|c0156a62]   Parameters: {"id"=>"9-babaroga2-test1-babaroga2-test1-debian-2disk-raid1-lvm-gpt"}
2019-07-29T17:09:25 [I|app|c0156a62] Current user set to admin (admin)
2019-07-29T17:09:25 [I|app|c0156a62]   Rendering hostgroups/edit.html.erb within layouts/application
2019-07-29T17:09:25 [I|app|c0156a62]   Rendered collection of puppetclasses/_selectedClasses.html.erb [0 times] (0.0ms)
2019-07-29T17:09:25 [I|app|c0156a62]   Rendered collection of puppetclasses/_classes_in_groups.html.erb [0 times] (0.0ms)
2019-07-29T17:09:25 [I|app|c0156a62]   Rendered puppetclasses/_classes.html.erb (0.1ms)
2019-07-29T17:09:25 [I|app|c0156a62]   Rendered puppetclasses/_class_selection.html.erb (135.7ms)
2019-07-29T17:09:25 [I|app|c0156a62]   Rendered common/os_selection/_architecture.html.erb (8.7ms)
2019-07-29T17:09:25 [I|app|c0156a62]   Rendered common/os_selection/_pxe_loader.html.erb (5.2ms)
2019-07-29T17:09:25 [I|app|c0156a62]   Rendered common/os_selection/_operatingsystem.html.erb (44.6ms)
2019-07-29T17:09:25 [I|app|c0156a62]   Rendered common/os_selection/_initial.html.erb (62.8ms)
2019-07-29T17:09:25 [I|app|c0156a62]   Rendered collection of puppetclasses/_class_parameters.html.erb [0 times] (0.0ms)
2019-07-29T17:09:25 [I|app|c0156a62]   Rendered puppetclasses/_classes_parameters.html.erb (22.7ms)
2019-07-29T17:09:25 [I|app|c0156a62]   Rendered common_parameters/_inherited_parameters.html.erb (3.7ms)
2019-07-29T17:09:25 [I|app|c0156a62]   Rendered common_parameters/_parameter.html.erb (2.3ms)
2019-07-29T17:09:25 [I|app|c0156a62]   Rendered common_parameters/_parameter.html.erb (1.9ms)
2019-07-29T17:09:25 [I|app|c0156a62]   Rendered common_parameters/_parameter.html.erb (2.0ms)
2019-07-29T17:09:25 [I|app|c0156a62]   Rendered common_parameters/_parameter.html.erb (1.9ms)
2019-07-29T17:09:25 [I|app|c0156a62]   Rendered common_parameters/_parameters.html.erb (12.6ms)
2019-07-29T17:09:26 [I|app|c0156a62]   Rendered taxonomies/_loc_org_tabs.html.erb (46.4ms)
2019-07-29T17:09:26 [I|app|c0156a62]   Rendered hostgroups/_form.html.erb (462.0ms)
2019-07-29T17:09:26 [I|app|c0156a62]   Rendered hostgroups/edit.html.erb within layouts/application (462.4ms)
2019-07-29T17:09:26 [I|app|c0156a62]   Rendered layouts/_application_content.html.erb (1.5ms)
2019-07-29T17:09:26 [I|app|c0156a62]   Rendering layouts/base.html.erb
2019-07-29T17:09:26 [I|app|c0156a62]   Rendered layouts/base.html.erb (26.8ms)
2019-07-29T17:09:26 [I|app|c0156a62] Completed 200 OK in 557ms (Views: 443.2ms | ActiveRecord: 63.1ms)
2019-07-29T17:09:27 [I|app|7e6ddd95] Started GET "/notification_recipients" for 10.93.0.1 at 2019-07-29 17:09:27 +0200
2019-07-29T17:09:27 [I|app|7e6ddd95] Processing by NotificationRecipientsController#index as JSON
2019-07-29T17:09:27 [I|app|7e6ddd95] Current user set to admin (admin)
2019-07-29T17:09:27 [I|app|7e6ddd95] Completed 200 OK in 14ms (Views: 0.2ms | ActiveRecord: 1.8ms)
2019-07-29T17:09:37 [I|app|5e72781a] Started GET "/notification_recipients" for 10.93.0.1 at 2019-07-29 17:09:37 +0200
2019-07-29T17:09:37 [I|app|5e72781a] Processing by NotificationRecipientsController#index as JSON
2019-07-29T17:09:37 [I|app|5e72781a] Current user set to admin (admin)
2019-07-29T17:09:37 [I|app|5e72781a] Completed 200 OK in 12ms (Views: 0.2ms | ActiveRecord: 1.7ms)
2019-07-29T17:09:46 [I|app|bc01fc94] Started GET "/templates/provisioning_templates" for 10.93.0.1 at 2019-07-29 17:09:46 +0200
2019-07-29T17:09:46 [I|app|bc01fc94] Processing by ProvisioningTemplatesController#index as HTML
2019-07-29T17:09:46 [I|app|bc01fc94] Current user set to admin (admin)
2019-07-29T17:09:46 [I|app|bc01fc94]   Rendering provisioning_templates/index.html.erb within layouts/application
2019-07-29T17:09:47 [I|app|bc01fc94]   Rendered common/_pagination.html.erb (0.5ms)
2019-07-29T17:09:47 [I|app|bc01fc94]   Rendered provisioning_templates/index.html.erb within layouts/application (234.6ms)
2019-07-29T17:09:47 [I|app|bc01fc94]   Rendered common/_searchbar.html.erb (0.5ms)
2019-07-29T17:09:47 [I|app|bc01fc94]   Rendered layouts/_application_content.html.erb (1.4ms)
2019-07-29T17:09:47 [I|app|bc01fc94]   Rendering layouts/base.html.erb
2019-07-29T17:09:47 [I|app|bc01fc94]   Rendered layouts/base.html.erb (27.2ms)
2019-07-29T17:09:47 [I|app|bc01fc94] Completed 200 OK in 290ms (Views: 258.9ms | ActiveRecord: 10.9ms)
2019-07-29T17:09:47 [I|app|f572bdbe] Started GET "/templates/provisioning_templates" for 10.93.0.1 at 2019-07-29 17:09:47 +0200
2019-07-29T17:09:47 [I|app|f572bdbe] Processing by ProvisioningTemplatesController#index as HTML
2019-07-29T17:09:47 [I|app|f572bdbe] Current user set to admin (admin)
2019-07-29T17:09:47 [I|app|f572bdbe]   Rendering provisioning_templates/index.html.erb within layouts/application
2019-07-29T17:09:47 [I|app|f572bdbe]   Rendered common/_pagination.html.erb (0.5ms)
2019-07-29T17:09:47 [I|app|f572bdbe]   Rendered provisioning_templates/index.html.erb within layouts/application (234.3ms)
2019-07-29T17:09:47 [I|app|f572bdbe]   Rendered common/_searchbar.html.erb (0.5ms)
2019-07-29T17:09:47 [I|app|f572bdbe]   Rendered layouts/_application_content.html.erb (1.3ms)
2019-07-29T17:09:47 [I|app|f572bdbe]   Rendering layouts/base.html.erb
2019-07-29T17:09:47 [I|app|e43173ac] Started GET "/notification_recipients" for 10.93.0.1 at 2019-07-29 17:09:47 +0200
2019-07-29T17:09:47 [I|app|e43173ac] Processing by NotificationRecipientsController#index as JSON
2019-07-29T17:09:47 [I|app|e43173ac] Current user set to admin (admin)
2019-07-29T17:09:47 [I|app|f572bdbe]   Rendered layouts/base.html.erb (28.4ms)
2019-07-29T17:09:47 [I|app|f572bdbe] Completed 200 OK in 292ms (Views: 261.2ms | ActiveRecord: 8.8ms)
2019-07-29T17:09:47 [I|app|e43173ac] Completed 200 OK in 14ms (Views: 0.3ms | ActiveRecord: 2.0ms)
2019-07-29T17:09:49 [I|app|125a5f00] Started GET "/notification_recipients" for 10.93.0.1 at 2019-07-29 17:09:49 +0200
2019-07-29T17:09:49 [I|app|125a5f00] Processing by NotificationRecipientsController#index as JSON
2019-07-29T17:09:49 [I|app|125a5f00] Current user set to admin (admin)
2019-07-29T17:09:49 [I|app|125a5f00] Completed 200 OK in 13ms (Views: 0.2ms | ActiveRecord: 1.7ms)
2019-07-29T17:09:54 [I|app|616880f2] Started GET "/templates/provisioning_templates/50-Preseed%20default/edit" for 10.93.0.1 at 2019-07-29 17:09:54 +0200
2019-07-29T17:09:54 [I|app|616880f2] Processing by ProvisioningTemplatesController#edit as HTML
2019-07-29T17:09:54 [I|app|616880f2]   Parameters: {"id"=>"50-Preseed default"}
2019-07-29T17:09:54 [I|app|616880f2] Current user set to admin (admin)
2019-07-29T17:09:54 [I|app|616880f2]   Rendering provisioning_templates/edit.html.erb within layouts/application
2019-07-29T17:09:54 [I|app|616880f2]   Rendered provisioning_templates/_custom_tab_headers.html.erb (0.1ms)
2019-07-29T17:09:54 [I|app|616880f2]   Rendered provisioning_templates/_alerts.html.erb (2.3ms)
2019-07-29T17:09:54 [I|app|616880f2]   Rendered editor/_toolbar.html.erb (0.8ms)
2019-07-29T17:09:54 [I|app|616880f2]   Rendered template_inputs/_form.html.erb (14.7ms)
2019-07-29T17:09:54 [I|app|616880f2]   Rendered templates/_history.html.erb (0.4ms)
2019-07-29T17:09:54 [I|app|616880f2]   Rendered templates/_help_accordion.html.erb (0.3ms)
2019-07-29T17:09:54 [I|app|616880f2]   Rendered templates/_help_accordion.html.erb (0.2ms)
2019-07-29T17:09:54 [I|app|616880f2]   Rendered templates/_help_accordion.html.erb (0.2ms)
2019-07-29T17:09:54 [I|app|616880f2]   Rendered templates/_help_accordion.html.erb (0.2ms)
2019-07-29T17:09:54 [I|app|616880f2]   Rendered templates/_help_accordion.html.erb (0.2ms)
2019-07-29T17:09:54 [I|app|616880f2]   Rendered templates/_help_accordion.html.erb (0.2ms)
2019-07-29T17:09:54 [I|app|616880f2]   Rendered templates/_help_accordion.html.erb (0.2ms)
2019-07-29T17:09:54 [I|app|616880f2]   Rendered templates/_help_accordion.html.erb (0.2ms)
2019-07-29T17:09:54 [I|app|616880f2]   Rendered templates/_help_accordion.html.erb (0.2ms)
2019-07-29T17:09:54 [I|app|616880f2]   Rendered provisioning_templates/_combination.html.erb (9.2ms)
2019-07-29T17:09:54 [I|app|616880f2]   Rendered provisioning_templates/_combinations.html.erb (11.5ms)
2019-07-29T17:09:54 [I|app|616880f2]   Rendered provisioning_templates/_custom_tabs.html.erb (23.0ms)
2019-07-29T17:09:54 [I|app|616880f2]   Rendered taxonomies/_loc_org_tabs.html.erb (16.1ms)
2019-07-29T17:09:54 [I|app|616880f2]   Rendered templates/_form.html.erb (73.4ms)
2019-07-29T17:09:54 [I|app|616880f2]   Rendered provisioning_templates/edit.html.erb within layouts/application (74.8ms)
2019-07-29T17:09:54 [I|app|616880f2]   Rendered layouts/_application_content.html.erb (0.3ms)
2019-07-29T17:09:54 [I|app|616880f2]   Rendering layouts/base.html.erb
2019-07-29T17:09:54 [I|app|616880f2]   Rendered layouts/base.html.erb (26.8ms)
2019-07-29T17:09:54 [I|app|616880f2] Completed 200 OK in 128ms (Views: 94.3ms | ActiveRecord: 13.9ms)
2019-07-29T17:09:54 [I|app|43d778ce] Started GET "/hosts/preview_host_collection?scope=ProvisioningTemplate" for 10.93.0.1 at 2019-07-29 17:09:54 +0200
2019-07-29T17:09:54 [I|app|43d778ce] Processing by HostsController#preview_host_collection as JSON
2019-07-29T17:09:54 [I|app|43d778ce]   Parameters: {"scope"=>"ProvisioningTemplate"}
2019-07-29T17:09:55 [I|app|43d778ce] Current user set to admin (admin)
2019-07-29T17:09:55 [I|app|43d778ce] Completed 200 OK in 29ms (Views: 1.1ms | ActiveRecord: 4.1ms)
2019-07-29T17:09:59 [I|app|3b8bb34f] Started GET "/notification_recipients" for 10.93.0.1 at 2019-07-29 17:09:59 +0200
2019-07-29T17:09:59 [I|app|3b8bb34f] Processing by NotificationRecipientsController#index as JSON
2019-07-29T17:09:59 [I|app|3b8bb34f] Current user set to admin (admin)
2019-07-29T17:09:59 [I|app|3b8bb34f] Completed 200 OK in 12ms (Views: 0.2ms | ActiveRecord: 1.8ms)
2019-07-29T17:10:09 [I|app|64377843] Started GET "/notification_recipients" for 10.93.0.1 at 2019-07-29 17:10:09 +0200
2019-07-29T17:10:09 [I|app|64377843] Processing by NotificationRecipientsController#index as JSON
2019-07-29T17:10:09 [I|app|64377843] Current user set to admin (admin)
2019-07-29T17:10:09 [I|app|64377843] Completed 200 OK in 12ms (Views: 0.3ms | ActiveRecord: 1.6ms)
2019-07-29T17:10:45 [I|app|68cc5b53] Started GET "/unattended/provision?token=890d02f0-3361-4bc1-bb8b-983eba999283&url=http%3A%2F%2Fforeman-2-proxy-1.babaroga2.local%3A8000" for foreman-2-proxy-1.babaroga2.local at 2019-07-29 17:10:45 +0200
2019-07-29T17:10:45 [I|app|68cc5b53] Processing by UnattendedController#host_template as TEXT
2019-07-29T17:10:45 [I|app|68cc5b53]   Parameters: {"token"=>"890d02f0-3361-4bc1-bb8b-983eba999283", "url"=>"http://foreman-2-proxy-1.babaroga2.local:8000", "kind"=>"provision", "unattended"=>{}}
2019-07-29T17:10:46 [I|app|68cc5b53]   Rendering text template
2019-07-29T17:10:46 [I|app|68cc5b53]   Rendered text template (0.0ms)
2019-07-29T17:10:46 [I|app|68cc5b53] Completed 200 OK in 208ms (Views: 0.8ms | ActiveRecord: 26.4ms)
2019-07-29T17:11:55 [I|dyn|] start terminating throttle_limiter...
2019-07-29T17:11:55 [I|dyn|] start terminating client dispatcher...
2019-07-29T17:11:55 [I|dyn|] stop listening for new events...
2019-07-29T17:11:55 [I|dyn|] start terminating clock...
2019-07-29T17:11:55 [I|dyn|] start terminating throttle_limiter...
2019-07-29T17:11:55 [I|dyn|] start terminating client dispatcher...
2019-07-29T17:11:55 [I|dyn|] stop listening for new events...
2019-07-29T17:11:55 [I|dyn|] start terminating clock...
2019-07-29T17:14:47 [I|dyn|] start terminating throttle_limiter...
2019-07-29T17:14:47 [I|dyn|] start terminating client dispatcher...
2019-07-29T17:14:47 [I|dyn|] stop listening for new events...
2019-07-29T17:14:47 [I|dyn|] start terminating clock...
2019-07-29T17:17:29 [I|app|cdc763e8] Started POST "/api/hosts/facts" for 10.137.100.20 at 2019-07-29 17:17:29 +0200
2019-07-29T17:17:29 [I|app|cdc763e8] Processing by Api::V2::HostsController#facts as JSON
2019-07-29T17:17:29 [I|app|cdc763e8]   Parameters: {"facts"=>"[FILTERED]", "name"=>"foreman-2-master.babaroga2.local", "certname"=>"foreman-2-master.babaroga2.local", "apiv"=>"v2", "host"=>{"certname"=>"foreman-2-master.babaroga2.local", "name"=>"foreman-2-master.babaroga2.local"}}
2019-07-29T17:17:29 [W|app|cdc763e8] No smart proxy server found on ["foreman-2-master.babaroga2.local", "puppet", "puppet.babaroga2.local"] and is not in trusted_hosts
2019-07-29T17:17:29 [I|app|cdc763e8]   Rendering api/v2/errors/access_denied.json.rabl within api/v2/layouts/error_layout
2019-07-29T17:17:29 [I|app|cdc763e8]   Rendered api/v2/errors/access_denied.json.rabl within api/v2/layouts/error_layout (0.4ms)
2019-07-29T17:17:29 [I|app|cdc763e8] Filter chain halted as #<Proc:0x0055de362cf3c0@/usr/share/foreman/app/controllers/concerns/foreman/controller/smart_proxy_auth.rb:14> rendered or redirected
2019-07-29T17:17:29 [I|app|cdc763e8] Completed 403 Forbidden in 42ms (Views: 1.4ms | ActiveRecord: 13.8ms)
2019-07-29T17:17:29 [I|app|fbcc8548] Started GET "/node/foreman-2-master.babaroga2.local?format=yml" for 10.137.100.20 at 2019-07-29 17:17:29 +0200
2019-07-29T17:17:29 [I|app|fbcc8548] Processing by HostsController#externalNodes as YML
2019-07-29T17:17:29 [I|app|fbcc8548]   Parameters: {"name"=>"foreman-2-master.babaroga2.local"}
2019-07-29T17:17:29 [W|app|fbcc8548] No smart proxy server found on ["foreman-2-master.babaroga2.local", "puppet", "puppet.babaroga2.local"] and is not in trusted_hosts
2019-07-29T17:17:29 [I|app|fbcc8548] Redirected to https://foreman-2-master.babaroga2.local/users/login
2019-07-29T17:17:29 [I|app|fbcc8548] Filter chain halted as #<Proc:0x0055de33ce01c8@/usr/share/foreman/app/controllers/concerns/foreman/controller/smart_proxy_auth.rb:14> rendered or redirected
2019-07-29T17:17:29 [I|app|fbcc8548] Completed 403 Forbidden in 11ms (ActiveRecord: 2.6ms)
2019-07-29T17:17:30 [I|app|116d2730] Started POST "/api/hosts/facts" for 10.137.100.20 at 2019-07-29 17:17:30 +0200
2019-07-29T17:17:30 [I|app|116d2730] Processing by Api::V2::HostsController#facts as JSON
2019-07-29T17:17:30 [I|app|116d2730]   Parameters: {"facts"=>"[FILTERED]", "name"=>"foreman-2-master.babaroga2.local", "certname"=>"foreman-2-master.babaroga2.local", "apiv"=>"v2", "host"=>{"certname"=>"foreman-2-master.babaroga2.local", "name"=>"foreman-2-master.babaroga2.local"}}
2019-07-29T17:17:30 [W|app|116d2730] No smart proxy server found on ["foreman-2-master.babaroga2.local", "puppet", "puppet.babaroga2.local"] and is not in trusted_hosts
2019-07-29T17:17:30 [I|app|116d2730]   Rendering api/v2/errors/access_denied.json.rabl within api/v2/layouts/error_layout
2019-07-29T17:17:30 [I|app|116d2730]   Rendered api/v2/errors/access_denied.json.rabl within api/v2/layouts/error_layout (0.3ms)
2019-07-29T17:17:30 [I|app|116d2730] Filter chain halted as #<Proc:0x0055de362cf3c0@/usr/share/foreman/app/controllers/concerns/foreman/controller/smart_proxy_auth.rb:14> rendered or redirected
2019-07-29T17:17:30 [I|app|116d2730] Completed 403 Forbidden in 13ms (Views: 1.3ms | ActiveRecord: 2.9ms)
2019-07-29T17:17:30 [I|app|2182402d] Started GET "/node/foreman-2-master.babaroga2.local?format=yml" for 10.137.100.20 at 2019-07-29 17:17:30 +0200
2019-07-29T17:17:30 [I|app|2182402d] Processing by HostsController#externalNodes as YML
2019-07-29T17:17:30 [I|app|2182402d]   Parameters: {"name"=>"foreman-2-master.babaroga2.local"}
2019-07-29T17:17:30 [W|app|2182402d] No smart proxy server found on ["foreman-2-master.babaroga2.local", "puppet", "puppet.babaroga2.local"] and is not in trusted_hosts
2019-07-29T17:17:30 [I|app|2182402d] Redirected to https://foreman-2-master.babaroga2.local/users/login
2019-07-29T17:17:30 [I|app|2182402d] Filter chain halted as #<Proc:0x0055de33ce01c8@/usr/share/foreman/app/controllers/concerns/foreman/controller/smart_proxy_auth.rb:14> rendered or redirected
2019-07-29T17:17:30 [I|app|2182402d] Completed 403 Forbidden in 10ms (ActiveRecord: 2.5ms)
2019-07-29T17:17:30 [I|app|14ef8c97] Started POST "/api/config_reports" for 10.137.100.20 at 2019-07-29 17:17:30 +0200
2019-07-29T17:17:30 [I|app|14ef8c97] Processing by Api::V2::ConfigReportsController#create as JSON
2019-07-29T17:17:30 [I|app|14ef8c97]   Parameters: {"config_report"=>"[FILTERED]", "apiv"=>"v2"}
2019-07-29T17:17:30 [W|app|14ef8c97] No smart proxy server found on ["foreman-2-master.babaroga2.local", "puppet", "puppet.babaroga2.local"] and is not in trusted_hosts
2019-07-29T17:17:30 [I|app|14ef8c97]   Rendering api/v2/errors/access_denied.json.rabl within api/v2/layouts/error_layout
2019-07-29T17:17:30 [I|app|14ef8c97]   Rendered api/v2/errors/access_denied.json.rabl within api/v2/layouts/error_layout (0.4ms)
2019-07-29T17:17:30 [I|app|14ef8c97] Filter chain halted as #<Proc:0x0055de34acc110@/usr/share/foreman/app/controllers/concerns/foreman/controller/smart_proxy_auth.rb:14> rendered or redirected
2019-07-29T17:17:30 [I|app|14ef8c97] Completed 403 Forbidden in 16ms (Views: 1.4ms | ActiveRecord: 3.0ms)
2019-07-29T17:30:10 [W|app|] Creating scope :completer_scope. Overwriting existing method Location.completer_scope.
2019-07-29T17:30:10 [W|app|] Creating scope :completer_scope. Overwriting existing method Organization.completer_scope.
2019-07-29T17:30:10 [W|app|] Creating scope :completer_scope. Overwriting existing method Location.completer_scope.
2019-07-29T17:30:10 [W|app|] Creating scope :completer_scope. Overwriting existing method Organization.completer_scope.
2019-07-29T17:30:12 [I|dyn|] start terminating throttle_limiter...
2019-07-29T17:30:12 [I|dyn|] start terminating client dispatcher...
2019-07-29T17:30:12 [I|dyn|] stop listening for new events...
2019-07-29T17:30:12 [I|dyn|] start terminating clock...
2019-07-29T17:30:12 [I|dyn|] start terminating throttle_limiter...
2019-07-29T17:30:12 [I|dyn|] start terminating client dispatcher...
2019-07-29T17:30:12 [I|dyn|] stop listening for new events...
2019-07-29T17:30:12 [I|dyn|] start terminating clock...
2019-07-29T17:37:19 [I|app|50879e3a] Started GET "/unattended/finish?token=890d02f0-3361-4bc1-bb8b-983eba999283&url=http%3A%2F%2Fforeman-2-proxy-1.babaroga2.local%3A8000" for foreman-2-proxy-1.babaroga2.local at 2019-07-29 17:37:19 +0200
2019-07-29T17:37:19 [I|app|50879e3a] Processing by UnattendedController#host_template as TEXT
2019-07-29T17:37:19 [I|app|50879e3a]   Parameters: {"token"=>"890d02f0-3361-4bc1-bb8b-983eba999283", "url"=>"http://foreman-2-proxy-1.babaroga2.local:8000", "kind"=>"finish", "unattended"=>{}}
2019-07-29T17:37:20 [I|app|50879e3a]   Rendering text template
2019-07-29T17:37:20 [I|app|50879e3a]   Rendered text template (0.0ms)
2019-07-29T17:37:20 [I|app|50879e3a] Completed 200 OK in 713ms (Views: 0.9ms | ActiveRecord: 62.8ms)
2019-07-29T17:37:21 [I|app|65dfc93d] Started POST "/unattended/built?token=890d02f0-3361-4bc1-bb8b-983eba999283&Content-Type=text%2Fplain&url=http%3A%2F%2Fforeman-2-proxy-1.babaroga2.local%3A8000" for foreman-2-proxy-1.babaroga2.local at 2019-07-29 17:37:21 +0200
2019-07-29T17:37:21 [I|app|65dfc93d] Processing by UnattendedController#built as TEXT
2019-07-29T17:37:21 [I|app|65dfc93d]   Parameters: {"token"=>"890d02f0-3361-4bc1-bb8b-983eba999283", "Content-Type"=>"text/plain", "url"=>"http://foreman-2-proxy-1.babaroga2.local:8000"}
2019-07-29T17:37:21 [I|app|65dfc93d] unattended: babaroga0030487e985e.babaroga2.local is built!
2019-07-29T17:37:22 [I|app|65dfc93d] Deploying TFTP PXELinux configuration for babaroga0030487e985e.babaroga2.local
2019-07-29T17:37:22 [I|app|65dfc93d] Deploying TFTP PXEGrub2 configuration for babaroga0030487e985e.babaroga2.local
2019-07-29T17:37:22 [I|app|65dfc93d] Deploying TFTP PXEGrub configuration for babaroga0030487e985e.babaroga2.local
2019-07-29T17:37:22 [I|app|65dfc93d] Deploying TFTP iPXE configuration for babaroga0030487e985e.babaroga2.local
2019-07-29T17:37:22 [I|app|65dfc93d] Processed 4 tasks from queue 'Host::Managed Main', completed 4/4
2019-07-29T17:37:22 [I|aud|65dfc93d] Host::Base (152) update event on build true, false
2019-07-29T17:37:22 [I|aud|65dfc93d] Host::Base (152) update event on installed_at , 2019-07-29 15:37:21 UTC
2019-07-29T17:37:22 [I|app|65dfc93d] Completed 201 Created in 941ms (ActiveRecord: 61.7ms)
1 Like
2

Hey, this looks like a race condition. The provisioning process takes some time (seconds) while discovered node upload facts in the meantime which lead to new host created.

Discovered hosts upload facts every 30 seconds by default, you can tune this up via kernel command line option fdi.uploadsleep. Honestly I think this is too much and probably bug - I think it was supposed to be 30 minutes (which is also the facter default checkin time).

We would probably need to do some extra step calling discovered node to “stop sending facts”. But as a workaround you can probably increase this to 1 hour and then you will suffer this very unlikely.

Please report back how it went and then we can change the default value.

3

Hmmm… i thought it was something like that, but then it would be visible in logs?

I have added few more test machines and let them boot to discovery image.

One host started reporting:
2019-08-01T13:23:14 [I|app|523e0486] Started POST "/api/v2/discovered_hosts/facts" for 10.137.100.121 at 2019-08-01 13:23:14 +0200

and finished:
2019-08-01T13:23:16 [I|app|523e0486] Completed 201 Created in 1800ms (Views: 2.1ms | ActiveRecord: 474.5ms)

Afther that, there is no more mention of this host in logs ?

Maybe i should try to delete it and see when it will reappear?

4

Hmmm does not look like the snippet you’ve sent confirms this:

[lzap@box Downloads]$ egrep '(Started POST|Started PATCH|Completed)' logs.txt 
2019-07-29T17:06:20 [I|app|89c294ff] Completed 200 OK in 104ms (Views: 50.5ms | ActiveRecord: 11.0ms)
2019-07-29T17:06:21 [I|app|9658e827] Completed 200 OK in 13ms (Views: 0.2ms | ActiveRecord: 1.7ms)
2019-07-29T17:06:27 [I|app|20dfc168] Completed 200 OK in 768ms (Views: 528.2ms | ActiveRecord: 69.5ms)
2019-07-29T17:06:27 [I|app|5e84f477] Completed 200 OK in 14ms (Views: 0.2ms | ActiveRecord: 1.7ms)
2019-07-29T17:06:38 [I|app|8f9a79d8] Completed 200 OK in 12ms (Views: 0.2ms | ActiveRecord: 1.7ms)
2019-07-29T17:06:48 [I|app|bf02f2bc] Completed 200 OK in 12ms (Views: 0.2ms | ActiveRecord: 1.8ms)
2019-07-29T17:06:52 [I|app|ea72d063] Started PATCH "/discovered_hosts/152" for 10.93.0.1 at 2019-07-29 17:06:52 +0200
2019-07-29T17:06:54 [I|app|03cc1238] Completed 200 OK in 18ms (Views: 8.3ms | ActiveRecord: 1.7ms)
2019-07-29T17:06:54 [I|app|ea72d063] Completed 302 Found in 2015ms (ActiveRecord: 116.7ms)
2019-07-29T17:06:54 [I|app|69d9a7c4] Completed 200 OK in 78ms (Views: 49.1ms | ActiveRecord: 8.7ms)
2019-07-29T17:06:55 [I|app|ba2ff443] Completed 200 OK in 90ms (Views: 45.0ms | ActiveRecord: 21.0ms)
2019-07-29T17:06:55 [I|app|b2604c26] Completed 200 OK in 359ms (Views: 50.3ms | ActiveRecord: 82.0ms)
2019-07-29T17:06:55 [I|app|e9364b92] Completed 200 OK in 30ms (Views: 5.4ms | ActiveRecord: 5.0ms)
2019-07-29T17:06:55 [I|app|33557f94] Completed 200 OK in 35ms (Views: 10.6ms | ActiveRecord: 4.3ms)
2019-07-29T17:06:56 [I|app|6481266d] Completed 200 OK in 835ms (Views: 380.8ms | ActiveRecord: 38.7ms)
2019-07-29T17:06:56 [I|app|deeb470e] Completed 200 OK in 1432ms (Views: 1408.5ms | ActiveRecord: 5.8ms)
2019-07-29T17:06:57 [I|app|28978f38] Started POST "/api/v2/discovered_hosts/facts" for 10.137.100.121 at 2019-07-29 17:06:57 +0200
2019-07-29T17:06:59 [I|app|28978f38] Completed 201 Created in 1777ms (Views: 2.2ms | ActiveRecord: 477.1ms)
2019-07-29T17:08:24 [I|app|cc511bdc] Completed 200 OK in 221ms (Views: 0.8ms | ActiveRecord: 30.4ms)
2019-07-29T17:08:58 [I|app|3b82ab2c] Completed 200 OK in 26ms (Views: 0.2ms | ActiveRecord: 4.5ms)
2019-07-29T17:09:09 [I|app|6793eff7] Completed 200 OK in 12ms (Views: 0.2ms | ActiveRecord: 1.7ms)
2019-07-29T17:09:13 [I|app|98558473] Completed 200 OK in 133ms (Views: 100.2ms | ActiveRecord: 14.5ms)
2019-07-29T17:09:19 [I|app|f7e6fb0f] Completed 200 OK in 14ms (Views: 0.2ms | ActiveRecord: 1.8ms)
2019-07-29T17:09:25 [I|app|ec85c833] Completed 200 OK in 558ms (Views: 441.8ms | ActiveRecord: 66.3ms)
2019-07-29T17:09:26 [I|app|c0156a62] Completed 200 OK in 557ms (Views: 443.2ms | ActiveRecord: 63.1ms)
2019-07-29T17:09:27 [I|app|7e6ddd95] Completed 200 OK in 14ms (Views: 0.2ms | ActiveRecord: 1.8ms)
2019-07-29T17:09:37 [I|app|5e72781a] Completed 200 OK in 12ms (Views: 0.2ms | ActiveRecord: 1.7ms)
2019-07-29T17:09:47 [I|app|bc01fc94] Completed 200 OK in 290ms (Views: 258.9ms | ActiveRecord: 10.9ms)
2019-07-29T17:09:47 [I|app|f572bdbe] Completed 200 OK in 292ms (Views: 261.2ms | ActiveRecord: 8.8ms)
2019-07-29T17:09:47 [I|app|e43173ac] Completed 200 OK in 14ms (Views: 0.3ms | ActiveRecord: 2.0ms)
2019-07-29T17:09:49 [I|app|125a5f00] Completed 200 OK in 13ms (Views: 0.2ms | ActiveRecord: 1.7ms)
2019-07-29T17:09:54 [I|app|616880f2] Completed 200 OK in 128ms (Views: 94.3ms | ActiveRecord: 13.9ms)
2019-07-29T17:09:55 [I|app|43d778ce] Completed 200 OK in 29ms (Views: 1.1ms | ActiveRecord: 4.1ms)
2019-07-29T17:09:59 [I|app|3b8bb34f] Completed 200 OK in 12ms (Views: 0.2ms | ActiveRecord: 1.8ms)
2019-07-29T17:10:09 [I|app|64377843] Completed 200 OK in 12ms (Views: 0.3ms | ActiveRecord: 1.6ms)
2019-07-29T17:10:46 [I|app|68cc5b53] Completed 200 OK in 208ms (Views: 0.8ms | ActiveRecord: 26.4ms)
2019-07-29T17:17:29 [I|app|cdc763e8] Started POST "/api/hosts/facts" for 10.137.100.20 at 2019-07-29 17:17:29 +0200
2019-07-29T17:17:29 [I|app|cdc763e8] Completed 403 Forbidden in 42ms (Views: 1.4ms | ActiveRecord: 13.8ms)
2019-07-29T17:17:29 [I|app|fbcc8548] Completed 403 Forbidden in 11ms (ActiveRecord: 2.6ms)
2019-07-29T17:17:30 [I|app|116d2730] Started POST "/api/hosts/facts" for 10.137.100.20 at 2019-07-29 17:17:30 +0200
2019-07-29T17:17:30 [I|app|116d2730] Completed 403 Forbidden in 13ms (Views: 1.3ms | ActiveRecord: 2.9ms)
2019-07-29T17:17:30 [I|app|2182402d] Completed 403 Forbidden in 10ms (ActiveRecord: 2.5ms)
2019-07-29T17:17:30 [I|app|14ef8c97] Started POST "/api/config_reports" for 10.137.100.20 at 2019-07-29 17:17:30 +0200
2019-07-29T17:17:30 [I|app|14ef8c97] Completed 403 Forbidden in 16ms (Views: 1.4ms | ActiveRecord: 3.0ms)
2019-07-29T17:37:20 [I|app|50879e3a] Completed 200 OK in 713ms (Views: 0.9ms | ActiveRecord: 62.8ms)
2019-07-29T17:37:21 [I|app|65dfc93d] Started POST "/unattended/built?token=890d02f0-3361-4bc1-bb8b-983eba999283&Content-Type=text%2Fplain&url=http%3A%2F%2Fforeman-2-proxy-1.babaroga2.local%3A8000" for foreman-2-proxy-1.babaroga2.local at 2019-07-29 17:37:21 +0200
2019-07-29T17:37:22 [I|app|65dfc93d] Completed 201 Created in 941ms (ActiveRecord: 61.7ms)

Well I don’t see any deviations in logs, maybe try to turn on debug log and reproduce once again.

Also I realized discovered node only uploads facts when there was a change. Anyway, I am updating the interval to 15 mins: Refactor #27502: Check facts every 15 minutes - Discovery - Foreman

Edit: Irrelevant - It is visible in the logs, I was not telling a made story but looking on your paste :slight_smile:

5

Of course, it is visible in my paste.
I am not talking about that.
I meant to say that i cannot see such updates in logs during my tests. I let some machines to boot FDI, and observe logs, i am not seeing any updates. OK, it makes sense that updates are visible only when facts are changed in some way.

Is it possible to adjust fdi.uploadsleep to never update any facts until i do it manually?

Is there any safety mechanism that can prevent two hosts (both provisioned or discovered) with same primary mac address or same hostname? This can lead to many potential problems that can be very harmful.

6

That sentence was supposed to be deleted, after investigations of your logs, I actually could not confirm this. I forgot to delete it. As I said, I have no idea what caused this so far.

Yes, Administer - Settings - Error on existing NIC. Set to true and if NIC/MAC already exists in the Foreman DB host will fail to discover.

1 Like
7

just did quick check.
i changed discovered host by adding a disk, and it is visible on FDI:

[root@fdi ~]# dmesg | tail
[421776.638146] ata5.00: 976773168 sectors, multi 0: LBA48 NCQ (depth 31/32), AA
[421776.639222] ata5.00: configured for UDMA/133
[421776.639237] ata5: EH complete
[421776.639407] scsi 4:0:0:0: Direct-Access     ATA      WDC WD5002ABYS-0 3B03 PQ: 0 ANSI: 5
[421776.659388] sd 4:0:0:0: Attached scsi generic sg2 type 0
[421776.659442] sd 4:0:0:0: [sdc] 976773168 512-byte logical blocks: (500 GB/465 GiB)
[421776.659674] sd 4:0:0:0: [sdc] Write Protect is off
[421776.659684] sd 4:0:0:0: [sdc] Mode Sense: 00 3a 00 00
[421776.659779] sd 4:0:0:0: [sdc] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[421776.670458] sd 4:0:0:0: [sdc] Attached SCSI disk

But, nothing changed in foreman, fdi didn’t upload its changed facts (also, nothing in logs). I did wait 1 hour):

discovered_hosts
discovered_hosts1427×223 10.7 KB

8

tnx!
thats exaxctly what i was looking for! :slight_smile:

9

Probably a bug? Since you have it opened, can you check this script which runs on the background (systemd service) and in a loop checks facts and reports back to Foreman:

10

how do i check it?
i see it is running:

[root@fdi ~]# ps aux | grep discovery
root      1619  0.0  0.4 120840 19604 tty1     Ssl+ Aug01   0:00 /usr/bin/ruby /usr/bin/discovery-menu
root      6549  0.0  0.0  11140   668 pts/0    S+   09:37   0:00 grep --color=auto discovery
root     32550  0.3  0.5 196100 22724 ?        Ssl  08:28   0:16 ruby /usr/bin/discovery-register

also, i have:

upload_sleep = cmdline("fdi.uploadsleep", 30).to_i rescue 30

in this script (i did apt-get update / upgrade today, i am on debian 9, foreman 1.22)

11

It should be logging into the system journal. However you can stop it and execute it manually its running as root I think. I don’t remember if it writes anything to STDOUT tho.

Also what would be interesting is to see “facter --json” output before and after you add the disk. Because the script does this and filters out some irrelevant facts (which change too often) and if there was a difference it calls Foreman.

12

After disk inserted:

[root@fdi ~]# facter --json | grep blockdevice
  "blockdevice_sda_size": 4000787030016,
  "blockdevice_sda_vendor": "ATA",
  "blockdevice_sda_model": "MB4000GCWDC",
  "blockdevice_sdb_size": 4000787030016,
  "blockdevice_sdb_vendor": "ATA",
  "blockdevice_sdb_model": "MB4000GCWLV",
  "blockdevice_sdc_size": 500107862016,
  "blockdevice_sdc_vendor": "ATA",
  "blockdevice_sdc_model": "WDC WD5002ABYS-0",
  "blockdevices": "sda,sdb,sdc",

When i run /usr/bin/discovery-register manually:

[root@fdi ~]# /usr/bin/discovery-register
^C/usr/bin/discovery-register:75:in `sleep': Interrupt
       from /usr/bin/discovery-register:75:in `<main>'

I had to interuppt it because it stays in fg. After that in foreman log:

2019-08-06T11:44:21 [I|app|ac8b4b1d] Started POST "/api/v2/discovered_hosts/facts" for 10.137.100.121 at 2019-08-06 11:44:21 +0200
2019-08-06T11:44:21 [I|app|ac8b4b1d] Processing by Api::V2::DiscoveredHostsController#facts as JSON
2019-08-06T11:44:21 [I|app|ac8b4b1d]   Parameters: {"facts"=>"[FILTERED]", "apiv"=>"v2", "discovered_host"=>{"facts"=>"[FILTERED]"}}
2019-08-06T11:44:22 [I|app|ac8b4b1d] Import facts for 'babaroga003048fe2878' completed. Added: 3, Updated: 1, Deleted 0 facts
2019-08-06T11:44:22 [I|app|ac8b4b1d] Detected subnet: babaroga2 with taxonomy ["Default Organization"]/["Default Location"]
2019-08-06T11:44:22 [I|app|ac8b4b1d] Assigned location: Default Location
2019-08-06T11:44:22 [I|app|ac8b4b1d] Assigned organization: Default Organization
2019-08-06T11:44:22 [I|app|ac8b4b1d] Completed 201 Created in 636ms (Views: 2.1ms | ActiveRecord: 142.6ms)
2019-08-06T11:44:51 [I|app|705e1462] Started POST "/api/v2/discovered_hosts/facts" for 10.137.100.121 at 2019-08-06 11:44:51 +0200
2019-08-06T11:44:51 [I|app|705e1462] Processing by Api::V2::DiscoveredHostsController#facts as JSON
2019-08-06T11:44:51 [I|app|705e1462]   Parameters: {"facts"=>"[FILTERED]", "apiv"=>"v2", "discovered_host"=>{"facts"=>"[FILTERED]"}}
2019-08-06T11:44:51 [I|app|705e1462] Import facts for 'babaroga003048fe2878' completed. Added: 0, Updated: 1, Deleted 3 facts
2019-08-06T11:44:51 [I|app|705e1462] Detected subnet: babaroga2 with taxonomy ["Default Organization"]/["Default Location"]
2019-08-06T11:44:51 [I|app|705e1462] Assigned location: Default Location
2019-08-06T11:44:51 [I|app|705e1462] Assigned organization: Default Organization
2019-08-06T11:44:51 [I|app|705e1462] Completed 201 Created in 554ms (Views: 1.9ms | ActiveRecord: 113.0ms)

foreman now shows: facts last updated: less then a minute ago
If you want, i can repeat procedure to get facter --json before and afteter?

13

In system journal i have entries with /usr/bin/discovery-register only if i run it manually.

14

something is wrong here… facts disd re-upload when i run discovery-register manually.
But, in Foreman discovered hosts, there are no new facts:

Screenshot_20190806_120819
Screenshot_20190806_1208191102×320 15.6 KB

15

if i do resend on fdi console, then foreman have correct facts:

fdi
fdi803×506 20.8 KB

after that:

Screenshot_20190806_121414
Screenshot_20190806_1214141141×382 20.7 KB

16

i did a fresh build of discovery image (i think there is only one change,and that is “check facts every 15 min”):

[root@c01-min-01 foreman-discovery-image]# git pull
...
From https://github.com/theforeman/foreman-discovery-image
   89b34d8..99e713c  master     -> origin/master
Updating 89b34d8..99e713c
Fast-forward
   root/usr/bin/discovery-register | 4 ++--
1 file changed, 2 insertions(+), 2 deletions(-)

After successful build, i put FDI onm PXE on proxy, deleted discovered host, removed 3rd disk and rebooted it. After FDI boot, i have host in foreman with 2 disks.

[root@fdi ~]# facter --json | grep blockdevice
  "blockdevice_sda_size": 4000787030016,
  "blockdevice_sda_vendor": "ATA",
  "blockdevice_sda_model": "MB4000GCWDC",
  "blockdevice_sdb_size": 4000787030016,
  "blockdevice_sdb_vendor": "ATA",
  "blockdevice_sdb_model": "MB4000GCWLV",
  "blockdevices": "sda,sdb",

[root@fdi ~]# dmesg | tail
[  166.761305] ata5.00: 976773168 sectors, multi 0: LBA48 NCQ (depth 31/32), AA
[  166.762353] ata5.00: configured for UDMA/133
[  166.762366] ata5: EH complete
[  166.762537] scsi 4:0:0:0: Direct-Access     ATA      WDC WD5002ABYS-0 3B03 PQ: 0 ANSI: 5
[  166.776965] sd 4:0:0:0: Attached scsi generic sg2 type 0
[  166.777044] sd 4:0:0:0: [sdc] 976773168 512-byte logical blocks: (500 GB/465 GiB)
[  166.777279] sd 4:0:0:0: [sdc] Write Protect is off
[  166.777286] sd 4:0:0:0: [sdc] Mode Sense: 00 3a 00 00
[  166.777374] sd 4:0:0:0: [sdc] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[  166.793620] sd 4:0:0:0: [sdc] Attached SCSI disk

[root@fdi ~]# facter --json | grep blockdevice
  "blockdevice_sda_size": 4000787030016,
  "blockdevice_sda_vendor": "ATA",
  "blockdevice_sda_model": "MB4000GCWDC",
  "blockdevice_sdb_size": 4000787030016,
  "blockdevice_sdb_vendor": "ATA",
  "blockdevice_sdb_model": "MB4000GCWLV",
  "blockdevice_sdc_size": 500107862016,
  "blockdevice_sdc_vendor": "ATA",
  "blockdevice_sdc_model": "WDC WD5002ABYS-0",
  "blockdevices": "sda,sdb,sdc",

But, facts are NOT automatically re-upladed to foreman (i waited 1 hour again)

[root@fdi ~]# journalctl --system | tail -80
Aug 06 10:25:44 fdi /usr/bin/discovery-register[1966]: Detecting the first NICs with link
Aug 06 10:25:44 fdi /usr/bin/discovery-register[1966]: Interface with link found: 00:30:48:fe:28:78 (enp2s0f0)
Aug 06 10:25:44 fdi /usr/bin/discovery-register[1966]: Detecting the first NICs with link
Aug 06 10:25:44 fdi /usr/bin/discovery-register[1966]: Interface with link found: 00:30:48:fe:28:78 (enp2s0f0)
Aug 06 10:25:44 fdi /usr/bin/discovery-register[1966]:  boardmanufacturer: Supermicro
Aug 06 10:25:44 fdi /usr/bin/discovery-register[1966]:  boardproductname: H8DGT
Aug 06 10:25:44 fdi /usr/bin/discovery-register[1966]:  hardwareisa: x86_64
Aug 06 10:25:44 fdi /usr/bin/discovery-register[1966]:  hardwaremodel: x86_64
Aug 06 10:25:44 fdi /usr/bin/discovery-register[1966]:  ipaddress: 10.137.111.176
Aug 06 10:25:44 fdi /usr/bin/discovery-register[1966]:  ipaddress_enp2s0f0: 10.137.111.176
Aug 06 10:25:44 fdi /usr/bin/discovery-register[1966]:  ipaddress_lo: 127.0.0.1
Aug 06 10:25:44 fdi /usr/bin/discovery-register[1966]:  ipmi_1_ipaddress: 10.137.101.208
Aug 06 10:25:44 fdi /usr/bin/discovery-register[1966]:  ipmi_1_ipaddress_source: DHCP Address
Aug 06 10:25:44 fdi /usr/bin/discovery-register[1966]:  ipmi_1_macaddress: 00:30:48:fe:28:7a
Aug 06 10:25:44 fdi /usr/bin/discovery-register[1966]:  ipmi_ipaddress: 10.137.101.208
Aug 06 10:25:44 fdi /usr/bin/discovery-register[1966]:  ipmi_ipaddress_source: DHCP Address
Aug 06 10:25:44 fdi /usr/bin/discovery-register[1966]:  ipmi_macaddress: 00:30:48:fe:28:7a
Aug 06 10:25:44 fdi /usr/bin/discovery-register[1966]:  macaddress: 00:30:48:fe:28:78
Aug 06 10:25:44 fdi /usr/bin/discovery-register[1966]:  macaddress_enp2s0f0: 00:30:48:fe:28:78
Aug 06 10:25:44 fdi /usr/bin/discovery-register[1966]:  macaddress_enp2s0f1: 00:30:48:fe:28:79
Aug 06 10:25:44 fdi /usr/bin/discovery-register[1966]:  manufacturer: Supermicro
Aug 06 10:25:44 fdi /usr/bin/discovery-register[1966]:  nmprimary_802-3-ethernet_cloned-mac-address:
Aug 06 10:25:44 fdi /usr/bin/discovery-register[1966]:  nmprimary_802-3-ethernet_generate-mac-address-mask:
Aug 06 10:25:44 fdi /usr/bin/discovery-register[1966]:  nmprimary_802-3-ethernet_mac-address: 00:30:48:FE:28:78
Aug 06 10:25:44 fdi /usr/bin/discovery-register[1966]:  nmprimary_802-3-ethernet_mac-address-blacklist:
Aug 06 10:25:44 fdi /usr/bin/discovery-register[1966]:  nmprimary_dhcp4_option_broadcast_address: 10.137.111.255
Aug 06 10:25:44 fdi /usr/bin/discovery-register[1966]:  nmprimary_dhcp4_option_ip_address: 10.137.111.176
Aug 06 10:25:44 fdi /usr/bin/discovery-register[1966]:  nmprimary_dhcp4_option_requested_broadcast_address: 1
Aug 06 10:25:44 fdi /usr/bin/discovery-register[1966]:  nmprimary_ip4_address: 10.137.111.176/24
Aug 06 10:25:44 fdi /usr/bin/discovery-register[1966]:  nmprimary_ip6_address: fe80::230:48ff:fefe:2878/64
Aug 06 10:25:44 fdi /usr/bin/discovery-register[1966]:  nmprimary_ipv4_addresses:
Aug 06 10:25:44 fdi /usr/bin/discovery-register[1966]:  nmprimary_ipv6_addresses:
Aug 06 10:25:44 fdi /usr/bin/discovery-register[1966]:  productname: H8DGT
Aug 06 10:25:44 fdi /usr/bin/discovery-register[1966]: Fact cache invalid, reloading to foreman
Aug 06 10:25:44 fdi /usr/bin/discovery-register[1966]: Discovered by URL: https://foreman-2-proxy-1.babaroga2.local:8443
Aug 06 10:25:44 fdi /usr/bin/discovery-register[1966]: Registering host at (https://foreman-2-proxy-1.babaroga2.local:8443)
Aug 06 10:25:46 fdi /usr/bin/discovery-register[1966]: Response from server 200:
Aug 06 10:25:46 fdi /usr/bin/discovery-register[1966]: Wrote result 200 to /tmp/discovery-http-success
Aug 06 10:25:47 fdi /usr/bin/discovery-menu[1640]: Entering screen_status
Aug 06 10:25:47 fdi /usr/bin/discovery-menu[1640]: Discovered by URL: https://foreman-2-proxy-1.babaroga2.local:8443
Aug 06 10:25:47 fdi /usr/bin/discovery-menu[1640]: Discovered by URL: https://foreman-2-proxy-1.babaroga2.local:8443
Aug 06 10:26:10 fdi sshd[2366]: Connection closed by 10.93.0.1 port 59956 [preauth]
Aug 06 10:26:21 fdi sshd[2368]: Accepted password for root from 10.93.0.1 port 59958 ssh2
Aug 06 10:26:21 fdi systemd[1]: Created slice User Slice of root.
Aug 06 10:26:21 fdi systemd-logind[1318]: New session 1 of user root.
Aug 06 10:26:21 fdi systemd[1]: Started Session 1 of user root.
Aug 06 10:26:21 fdi sshd[2368]: pam_unix(sshd:session): session opened for user root by (uid=0)
Aug 06 10:26:35 fdi kernel: random: crng init done
Aug 06 10:26:38 fdi /usr/bin/facter[2383]: Detecting the first NICs with link
Aug 06 10:26:38 fdi /usr/bin/facter[2383]: Interface with link found: 00:30:48:fe:28:78 (enp2s0f0)
Aug 06 10:26:38 fdi /usr/bin/facter[2383]: Detecting the first NICs with link
Aug 06 10:26:38 fdi /usr/bin/facter[2383]: Interface with link found: 00:30:48:fe:28:78 (enp2s0f0)
Aug 06 10:27:06 fdi /usr/bin/facter[2689]: Detecting the first NICs with link
Aug 06 10:27:06 fdi /usr/bin/facter[2689]: Interface with link found: 00:30:48:fe:28:78 (enp2s0f0)
Aug 06 10:27:06 fdi /usr/bin/facter[2689]: Detecting the first NICs with link
Aug 06 10:27:06 fdi /usr/bin/facter[2689]: Interface with link found: 00:30:48:fe:28:78 (enp2s0f0)
Aug 06 10:27:18 fdi kernel: ata5: exception Emask 0x10 SAct 0x0 SErr 0x40d0000 action 0xe frozen
Aug 06 10:27:18 fdi kernel: ata5: irq_stat 0x00400040, connection status changed
Aug 06 10:27:18 fdi kernel: ata5: SError: { PHYRdyChg CommWake 10B8B DevExch }
Aug 06 10:27:18 fdi kernel: ata5: hard resetting link
Aug 06 10:27:28 fdi kernel: ata5: softreset failed (device not ready)
Aug 06 10:27:28 fdi kernel: ata5: hard resetting link
Aug 06 10:27:29 fdi kernel: ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Aug 06 10:27:29 fdi kernel: ata5.00: ATA-8: WDC WD5002ABYS-02B1B0, 02.03B03, max UDMA/133
Aug 06 10:27:29 fdi kernel: ata5.00: 976773168 sectors, multi 0: LBA48 NCQ (depth 31/32), AA
Aug 06 10:27:29 fdi kernel: ata5.00: configured for UDMA/133
Aug 06 10:27:29 fdi kernel: ata5: EH complete
Aug 06 10:27:29 fdi kernel: scsi 4:0:0:0: Direct-Access     ATA      WDC WD5002ABYS-0 3B03 PQ: 0 ANSI: 5
Aug 06 10:27:29 fdi kernel: sd 4:0:0:0: Attached scsi generic sg2 type 0
Aug 06 10:27:29 fdi kernel: sd 4:0:0:0: [sdc] 976773168 512-byte logical blocks: (500 GB/465 GiB)
Aug 06 10:27:29 fdi kernel: sd 4:0:0:0: [sdc] Write Protect is off
Aug 06 10:27:29 fdi kernel: sd 4:0:0:0: [sdc] Mode Sense: 00 3a 00 00
Aug 06 10:27:29 fdi kernel: sd 4:0:0:0: [sdc] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Aug 06 10:27:29 fdi kernel: sd 4:0:0:0: [sdc] Attached SCSI disk
Aug 06 10:27:42 fdi /usr/bin/facter[3001]: Detecting the first NICs with link
Aug 06 10:27:42 fdi /usr/bin/facter[3001]: Interface with link found: 00:30:48:fe:28:78 (enp2s0f0)
Aug 06 10:27:42 fdi /usr/bin/facter[3001]: Detecting the first NICs with link
Aug 06 10:27:42 fdi /usr/bin/facter[3001]: Interface with link found: 00:30:48:fe:28:78 (enp2s0f0)
Aug 06 10:40:16 fdi systemd[1]: Starting Cleanup of Temporary Directories...
Aug 06 10:40:16 fdi systemd[1]: Started Cleanup of Temporary Directories.

[root@fdi ~]# date
Tue Aug  6 11:25:35 UTC 2019
17

Is this PID still running? It should be it is an endless loop. Can you figure out why its not picking up the changes?

Edit: Whats in ‘/tmp/proxy_cache’

18

Found the issue, hold on.

19

@nbelavic can you try this patch?

Edit: When testing this let it run for a while and make sure it writes “No change in facts” to the log if there are no hardware changes performed. We must not reupload facts when there is no reason.

20

Will try this tomorrow :slight_smile:

1 Like