For the record, to reproduce edit a host and switch PXELoader to different type.
The root cause for this is that the record is deleted twice - the second attempt fails, then created via rollback.
2019-02-19T15:18:10 fc2306aa [I] Started GET /192.168.199.0/mac/00:c0:3a:d1:01:8f
2019-02-19T15:18:10 fc2306aa [I] Finished GET /192.168.199.0/mac/00:c0:3a:d1:01:8f with 200 (0.78 ms)
2019-02-19T15:18:10 fc2306aa [I] Started GET /192.168.199.0/ip/192.168.199.15
2019-02-19T15:18:10 fc2306aa [I] Finished GET /192.168.199.0/ip/192.168.199.15 with 200 (0.73 ms)
2019-02-19T15:18:10 fc2306aa [I] Started GET /192.168.199.0/mac/00:c0:3a:d1:01:8f
2019-02-19T15:18:10 fc2306aa [I] Finished GET /192.168.199.0/mac/00:c0:3a:d1:01:8f with 200 (0.82 ms)
2019-02-19T15:18:10 fc2306aa [I] Started GET /192.168.199.0/ip/192.168.199.15
2019-02-19T15:18:10 fc2306aa [I] Finished GET /192.168.199.0/ip/192.168.199.15 with 200 (0.7 ms)
2019-02-19T15:18:10 fc2306aa [I] Started DELETE /192.168.199.0/mac/00:c0:3a:d1:01:8f
2019-02-19T15:18:10 fc2306aa [I] Finished DELETE /192.168.199.0/mac/00:c0:3a:d1:01:8f with 200 (84.86 ms)
2019-02-19T15:18:10 fc2306aa [I] Started GET /serverName
2019-02-19T15:18:10 fc2306aa [I] Finished GET /serverName with 200 (0.56 ms)
2019-02-19T15:18:10 fc2306aa [I] Started DELETE /192.168.199.0/mac/00:c0:3a:d1:01:8f
2019-02-19T15:18:10 fc2306aa [I] Finished DELETE /192.168.199.0/mac/00:c0:3a:d1:01:8f with 400 (1.41 ms)
2019-02-19T15:18:10 fc2306aa [I] Started GET /192.168.199.0/mac/00:c0:3a:d1:01:8f
2019-02-19T15:18:10 fc2306aa [I] Finished GET /192.168.199.0/mac/00:c0:3a:d1:01:8f with 200 (0.72 ms)
2019-02-19T15:18:11 fc2306aa [I] Started GET /192.168.199.0/ip/192.168.199.15
2019-02-19T15:18:11 fc2306aa [I] Finished GET /192.168.199.0/ip/192.168.199.15 with 200 (0.66 ms)
2019-02-19T15:18:11 fc2306aa [I] Started POST /192.168.199.0
2019-02-19T15:18:11 fc2306aa [I] Finished POST /192.168.199.0 with 200 (70.5 ms)
The record is correctly deleted, then the second deletion fails with 400 (because proxy only see lease which is read-only thus the error message) and created back via rollback orchestrated by the Foreman:
host mac00c03ad1018f.nat.lan {
dynamic;
deleted;
}
host mac00c03ad1018f.nat.lan {
dynamic;
hardware ethernet 00:c0:3a:d1:01:8f;
fixed-address 192.168.199.15;
supersede server.filename = "pxelinux.0";
supersede server.next-server = c0:a8:c7:0b;
supersede host-name = "mac00c03ad1018f.nat.lan";
}
The UI errors out with ugly: Remove DHCP Settings for mac00c03ad1018f.nat.lan task failed with the following error: ERF12-0635 [ProxyAPI::ProxyException]: Unable to delete DHCP entry for 00:c0:3a:d1:01:8f ([RestClient::BadRequest]: 400 Bad Request) for Capsule https://sat65.nat.lan:9090/dhcp
The whole transaction is:
[root@sat65 ~]# grep fa3ed186 /var/log/foreman/production.log
2019-02-19T15:23:13 [I|app|fa3ed186] Processing by HostsController#update as */*
2019-02-19T15:23:13 [I|app|fa3ed186] Parameters: {"utf8"=>"✓", "authenticity_token"=>"fAfmRv1CI5w89PGSPbkSvg3rxaxftt7uBqYlvE62lmsrn5rbWCk3yjvGZU3nrfNsJhX6FzmLrxjRtV63wb8LyA==", "host"=>{"name"=>"mac00c03ad1018f", "hostgroup_id"=>"9", "content_facet_attributes"=>{"lifecycle_environment_id"=>"", "content_view_id"=>"", "content_source_id"=>""}, "environment_id"=>"1", "puppet_proxy_id"=>"1", "puppet_ca_proxy_id"=>"1", "openscap_proxy_id"=>"", "ansible_role_ids"=>[""], "puppetclass_ids"=>[""], "managed"=>"true", "progress_report_id"=>"[FILTERED]", "interfaces_attributes"=>{"0"=>{"_destroy"=>"0", "mac"=>"00:c0:3a:d1:01:8f", "identifier"=>"enp3s0", "name"=>"mac00c03ad1018f", "domain_id"=>"1", "subnet_id"=>"1", "ip"=>"192.168.199.15", "ip6"=>"", "managed"=>"1", "primary"=>"1", "provision"=>"1", "execution"=>"1", "tag"=>"", "attached_to"=>"", "id"=>"5"}, "1"=>{"_destroy"=>"0", "mac"=>"00:c0:3a:d1:41:8f", "identifier"=>"enp4s0", "name"=>"", "domain_id"=>"", "subnet_id"=>"", "ip"=>"", "ip6"=>"", "managed"=>"0", "primary"=>"0", "provision"=>"0", "execution"=>"0", "tag"=>"", "attached_to"=>"", "id"=>"6"}, "2"=>{"_destroy"=>"0", "mac"=>"00:c0:3a:d1:81:8f", "identifier"=>"enp5s0", "name"=>"", "domain_id"=>"", "subnet_id"=>"", "ip"=>"", "ip6"=>"", "managed"=>"0", "primary"=>"0", "provision"=>"0", "execution"=>"0", "tag"=>"", "attached_to"=>"", "id"=>"7"}, "3"=>{"_destroy"=>"0", "mac"=>"00:c0:3a:d1:c1:8f", "identifier"=>"enp6s0", "name"=>"", "domain_id"=>"", "subnet_id"=>"", "ip"=>"", "ip6"=>"", "managed"=>"0", "primary"=>"0", "provision"=>"0", "execution"=>"0", "tag"=>"", "attached_to"=>"", "id"=>"8"}}, "architecture_id"=>"1", "operatingsystem_id"=>"9", "medium_id"=>"11", "ptable_id"=>"99", "pxe_loader"=>"Grub2 UEFI", "disk"=>"", "root_pass"=>"[FILTERED]", "is_owned_by"=>"4-Users", "enabled"=>"1", "model_id"=>"2", "comment"=>"", "overwrite"=>"true"}, "media_selector"=>"install_media", "id"=>"5"}
2019-02-19T15:23:13 [I|app|fa3ed186] Current user set to admin (admin)
2019-02-19T15:23:13 [D|app|fa3ed186] Current location set to none
2019-02-19T15:23:13 [D|app|fa3ed186] Current organization set to MyOrg
2019-02-19T15:23:13 [D|app|fa3ed186] Current organization set to none
2019-02-19T15:23:14 [D|app|fa3ed186] Current location set to none
2019-02-19T15:23:14 [D|app|fa3ed186] Unpermitted parameter: :media_selector
2019-02-19T15:23:14 [D|app|fa3ed186] Comparing ["00:c0:3a:d1:01:8f", "192.168.199.15", "192.168.199.0", "pxelinux.0"] == ["00:c0:3a:d1:01:8f", "192.168.199.15", "192.168.199.0", "grub2/grubx64.efi"]
2019-02-19T15:23:14 [D|app|fa3ed186] Comparing ["00:c0:3a:d1:01:8f", "192.168.199.15", "192.168.199.0", "pxelinux.0"] == ["00:c0:3a:d1:01:8f", "192.168.199.15", "192.168.199.0", "grub2/grubx64.efi"]
2019-02-19T15:23:14 [D|app|fa3ed186] Scheduling DHCP conflicts removal
2019-02-19T15:23:14 [D|app|fa3ed186] Enqueued task 'dhcp_conflicts_remove_00:c0:3a:d1:01:8f' to 'Host::Managed Main' queue
2019-02-19T15:23:14 [D|app|fa3ed186] Detected a changed required for DHCP record
2019-02-19T15:23:14 [D|app|fa3ed186] Enqueued task 'dhcp_remove_00:c0:3a:d1:01:8f' to 'Host::Managed Main' queue
2019-02-19T15:23:14 [D|app|fa3ed186] Enqueued task 'dhcp_create_00:c0:3a:d1:01:8f' to 'Host::Managed Main' queue
2019-02-19T15:23:14 [D|app|fa3ed186] Scheduling DNS conflict removal
2019-02-19T15:23:14 [D|app|fa3ed186] Current organization set to MyOrg
2019-02-19T15:23:14 [D|app|fa3ed186] Current location set to MyLoc
2019-02-19T15:23:14 [D|app|fa3ed186] Current location set to none
2019-02-19T15:23:14 [D|app|fa3ed186] Current organization set to none
2019-02-19T15:23:14 [D|app|fa3ed186] Processing task 'DHCP conflicts removal for mac00c03ad1018f.nat.lan' from 'Host::Managed Main'
2019-02-19T15:23:14 [D|app|fa3ed186] Comparing ["00:c0:3a:d1:01:8f", "192.168.199.15", "192.168.199.0", "pxelinux.0"] == ["00:c0:3a:d1:01:8f", "192.168.199.15", "192.168.199.0", "grub2/grubx64.efi"]
2019-02-19T15:23:14 [D|app|fa3ed186] Comparing ["00:c0:3a:d1:01:8f", "192.168.199.15", "192.168.199.0", "pxelinux.0"] == ["00:c0:3a:d1:01:8f", "192.168.199.15", "192.168.199.0", "grub2/grubx64.efi"]
2019-02-19T15:23:14 [I|app|fa3ed186] Delete DHCP reservation mac00c03ad1018f.nat.lan for mac00c03ad1018f.nat.lan-00:c0:3a:d1:01:8f/192.168.199.15
2019-02-19T15:23:14 [D|app|fa3ed186] Processing task 'Remove DHCP Settings for mac00c03ad1018f.nat.lan' from 'Host::Managed Main'
2019-02-19T15:23:15 [I|app|fa3ed186] Delete DHCP reservation mac00c03ad1018f.nat.lan for mac00c03ad1018f.nat.lan-00:c0:3a:d1:01:8f/192.168.199.15
2019-02-19T15:23:15 [W|app|fa3ed186] Remove DHCP Settings for mac00c03ad1018f.nat.lan task failed with the following error: ERF12-0635 [ProxyAPI::ProxyException]: Unable to delete DHCP entry for 00:c0:3a:d1:01:8f ([RestClient::BadRequest]: 400 Bad Request) for Capsule https://sat65.nat.lan:9090/dhcp
2019-02-19T15:23:15 [W|app|fa3ed186] Rolling back due to a problem: [#<Orchestration::Task:0x000000001080dd00 @name="Remove DHCP Settings for mac00c03ad1018f.nat.lan", @id="dhcp_remove_00:c0:3a:d1:01:8f", @status="failed", @priority=5, @action=[#<Nic::Managed id: nil, mac: "00:c0:3a:d1:01:8f", ip: "192.168.199.15", type: "Nic::Managed", name: "mac00c03ad1018f.nat.lan", host_id: nil, subnet_id: 1, domain_id: 1, attrs: {"netmask"=>"255.255.255.0", "mtu"=>1500, "network"=>"192.168.199.0", "speed"=>"100", "duplex"=>"full", "port"=>"Twisted Pair", "auto_negotiation"=>"true", "wol"=>true}, created_at: nil, updated_at: nil, provider: nil, username: nil, password: nil, virtual: false, link: true, identifier: "enp3s0", tag: "", attached_to: "", managed: true, mode: "balance-rr", attached_devices: "", bond_options: "", primary: true, provision: true, compute_attributes: {}, execution: true, ip6: nil, subnet6_id: nil>, :del_dhcp], @created=1550589794.6106012, @timestamp=2019-02-19 15:23:15 UTC>]
2019-02-19T15:23:15 [I|app|fa3ed186] Create DHCP reservation mac00c03ad1018f.nat.lan for mac00c03ad1018f.nat.lan-00:c0:3a:d1:01:8f/192.168.199.15
2019-02-19T15:23:15 [D|app|fa3ed186] DHCP reservation on net 192.168.199.0 with attrs: {:hostname=>"mac00c03ad1018f.nat.lan", :mac=>"00:c0:3a:d1:01:8f", :ip=>"192.168.199.15", :network=>"192.168.199.0", :nextServer=>"192.168.199.11", :filename=>"pxelinux.0", :name=>"mac00c03ad1018f.nat.lan", :related_macs=>[], :type=>"reservation"}
2019-02-19T15:23:15 [I|app|fa3ed186] Processed 1 tasks from queue 'Host::Managed Main', completed 0/3
2019-02-19T15:23:15 [E|app|fa3ed186] Task 'DHCP conflicts removal for mac00c03ad1018f.nat.lan' *rollbacked*
2019-02-19T15:23:15 [E|app|fa3ed186] Task 'Remove DHCP Settings for mac00c03ad1018f.nat.lan' *failed*
2019-02-19T15:23:15 [E|app|fa3ed186] Task 'Create DHCP Settings for mac00c03ad1018f.nat.lan' *canceled*
2019-02-19T15:23:15 [E|app|fa3ed186] Failed to save: Remove DHCP Settings for mac00c03ad1018f.nat.lan task failed with the following error: ERF12-0635 [ProxyAPI::ProxyException]: Unable to delete DHCP entry for 00:c0:3a:d1:01:8f ([RestClient::BadRequest]: 400 Bad Request) for Capsule https://sat65.nat.lan:9090/dhcp
2019-02-19T15:23:15 [I|app|fa3ed186] Rendering hosts/edit.html.erb within layouts/application
2019-02-19T15:23:15 [D|app|fa3ed186] Deface: 3 overrides found for 'hosts/_form'
2019-02-19T15:23:15 [D|app|fa3ed186] Deface: 'add_execution_interface_js' matched 1 times with 'div#primary'
2019-02-19T15:23:15 [I|app|fa3ed186] Deface: [WARNING] No :original defined for 'add_execution_interface_js', you should change its definition to include:
2019-02-19T15:23:15 [D|app|fa3ed186] Deface: 'ansible_roles_tab' matched 1 times with 'li.active'
2019-02-19T15:23:15 [I|app|fa3ed186] Deface: [WARNING] No :original defined for 'ansible_roles_tab', you should change its definition to include:
2019-02-19T15:23:15 [D|app|fa3ed186] Deface: 'ansible_roles_tab_content' matched 1 times with 'div.tab-pane.active'
2019-02-19T15:23:15 [I|app|fa3ed186] Deface: [WARNING] No :original defined for 'ansible_roles_tab_content', you should change its definition to include:
2019-02-19T15:23:15 [I|app|fa3ed186] Rendered hosts/_progress.html.erb (1.2ms)
2019-02-19T15:23:15 [D|app|fa3ed186] Current organization set to MyOrg
2019-02-19T15:23:15 [D|app|fa3ed186] Current location set to MyLoc
2019-02-19T15:23:15 [I|app|fa3ed186] Rendered /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.10.0.19/app/views/overrides/activation_keys/_host_environment_select.html.erb (39.9ms)
2019-02-19T15:23:15 [I|app|fa3ed186] Rendered hosts/puppet/_main_tab_fields.html.erb (9.2ms)
2019-02-19T15:23:15 [I|app|fa3ed186] Rendered collection of puppetclasses/_selectedClasses.html.erb [0 times] (0.0ms)
2019-02-19T15:23:15 [I|app|fa3ed186] Rendered collection of puppetclasses/_classes_in_groups.html.erb [0 times] (0.0ms)
2019-02-19T15:23:15 [I|app|fa3ed186] Rendered puppetclasses/_classes.html.erb (0.8ms)
2019-02-19T15:23:15 [I|app|fa3ed186] Rendered puppetclasses/_class_selection.html.erb (80.0ms)
2019-02-19T15:23:15 [I|app|fa3ed186] Rendered hosts/puppet/_puppet_classes_tab.html.erb (97.2ms)
2019-02-19T15:23:15 [D|app|fa3ed186] Deface: 1 overrides found for 'nic/_base_form'
2019-02-19T15:23:15 [D|app|fa3ed186] Deface: 'add_execution_interface' matched 1 times with 'erb[loud]:contains("interface_provision")'
2019-02-19T15:23:15 [I|app|fa3ed186] Deface: [WARNING] No :original defined for 'add_execution_interface', you should change its definition to include:
2019-02-19T15:23:15 [I|app|fa3ed186] Rendered nic/_base_form.html.erb (75.1ms)
2019-02-19T15:23:15 [I|app|fa3ed186] Rendered nic/_virtual_form.html.erb (3.7ms)
2019-02-19T15:23:15 [I|app|fa3ed186] Rendered nic/_provider_specific_form.html.erb (0.7ms)
2019-02-19T15:23:15 [I|app|fa3ed186] Rendered nic/manageds/_managed.html.erb (127.2ms)
2019-02-19T15:23:15 [I|app|fa3ed186] Rendered nic/_base_form.html.erb (44.2ms)
2019-02-19T15:23:15 [I|app|fa3ed186] Rendered nic/_virtual_form.html.erb (1.2ms)
2019-02-19T15:23:15 [I|app|fa3ed186] Rendered nic/_provider_specific_form.html.erb (0.1ms)
2019-02-19T15:23:15 [I|app|fa3ed186] Rendered nic/manageds/_managed.html.erb (46.9ms)
2019-02-19T15:23:15 [I|app|fa3ed186] Rendered nic/_base_form.html.erb (44.7ms)
2019-02-19T15:23:15 [I|app|fa3ed186] Rendered nic/_virtual_form.html.erb (1.2ms)
2019-02-19T15:23:15 [I|app|fa3ed186] Rendered nic/_provider_specific_form.html.erb (0.1ms)
2019-02-19T15:23:15 [I|app|fa3ed186] Rendered nic/manageds/_managed.html.erb (47.3ms)
2019-02-19T15:23:15 [I|app|fa3ed186] Rendered nic/_base_form.html.erb (42.5ms)
2019-02-19T15:23:15 [I|app|fa3ed186] Rendered nic/_virtual_form.html.erb (1.1ms)
2019-02-19T15:23:15 [I|app|fa3ed186] Rendered nic/_provider_specific_form.html.erb (0.1ms)
2019-02-19T15:23:15 [I|app|fa3ed186] Rendered nic/manageds/_managed.html.erb (45.0ms)
2019-02-19T15:23:15 [I|app|fa3ed186] Rendered nic/_base_form.html.erb (43.0ms)
2019-02-19T15:23:15 [I|app|fa3ed186] Rendered nic/_virtual_form.html.erb (1.2ms)
2019-02-19T15:23:15 [I|app|fa3ed186] Rendered nic/_provider_specific_form.html.erb (0.1ms)
2019-02-19T15:23:15 [I|app|fa3ed186] Rendered nic/manageds/_managed.html.erb (49.4ms)
2019-02-19T15:23:15 [I|app|fa3ed186] Rendered hosts/_interfaces.html.erb (336.4ms)
2019-02-19T15:23:16 [I|app|fa3ed186] Rendered common/os_selection/_architecture.html.erb (8.5ms)
2019-02-19T15:23:16 [I|app|fa3ed186] Rendered /opt/theforeman/tfm/root/usr/share/gems/gems/foreman_bootdisk-14.0.0.1/app/views/hosts/provision_method/bootdisk/_form.html.erb (0.7ms)
2019-02-19T15:23:16 [D|app|fa3ed186] Deface: 2 overrides found for 'common/os_selection/_operatingsystem'
2019-02-19T15:23:16 [D|app|fa3ed186] Deface: 'hosts_select_media_type' matched 1 times with 'erb[loud]:contains("select_f"):contains(":medium_id")'
2019-02-19T15:23:16 [I|app|fa3ed186] Deface: [WARNING] No :original defined for 'hosts_select_media_type', you should change its definition to include:
2019-02-19T15:23:16 [D|app|fa3ed186] Deface: 'hosts_select_synced_content' matched 1 times with 'erb[loud]:contains("select_f"):contains(":medium_id")'
2019-02-19T15:23:16 [I|app|fa3ed186] Deface: [WARNING] No :original defined for 'hosts_select_synced_content', you should change its definition to include:
2019-02-19T15:23:16 [I|app|fa3ed186] Rendered common/os_selection/_pxe_loader.html.erb (2.3ms)
2019-02-19T15:23:16 [I|app|fa3ed186] Rendered common/os_selection/_operatingsystem.html.erb (104.2ms)
2019-02-19T15:23:16 [I|app|fa3ed186] Rendered hosts/provision_method/build/_form.html.erb (124.0ms)
2019-02-19T15:23:16 [I|app|fa3ed186] Rendered hosts/provision_method/image/_form.html.erb (0.9ms)
2019-02-19T15:23:16 [I|app|fa3ed186] Rendered hosts/_operating_system.html.erb (225.3ms)
2019-02-19T15:23:16 [I|app|fa3ed186] Rendered hosts/_unattended.html.erb (229.8ms)
2019-02-19T15:23:16 [I|app|fa3ed186] Rendered collection of puppetclasses/_class_parameters.html.erb [0 times] (0.0ms)
2019-02-19T15:23:16 [I|app|fa3ed186] Rendered puppetclasses/_classes_parameters.html.erb (33.8ms)
2019-02-19T15:23:16 [I|app|fa3ed186] Rendered common_parameters/_inherited_parameters.html.erb (7.0ms)
2019-02-19T15:23:16 [I|app|fa3ed186] Rendered common_parameters/_parameter.html.erb (3.9ms)
2019-02-19T15:23:16 [I|app|fa3ed186] Rendered common_parameters/_parameters.html.erb (19.0ms)
2019-02-19T15:23:16 [D|app|fa3ed186] Current location set to none
2019-02-19T15:23:16 [D|app|fa3ed186] Current organization set to none
2019-02-19T15:23:16 [I|app|fa3ed186] Rendered hosts/_form.html.erb (1039.3ms)
2019-02-19T15:23:16 [I|app|fa3ed186] Rendered hosts/edit.html.erb within layouts/application (1073.9ms)
2019-02-19T15:23:16 [I|app|fa3ed186] Rendered layouts/_application_content.html.erb (1.9ms)
2019-02-19T15:23:16 [D|app|fa3ed186] Deface: 1 overrides found for 'layouts/base'
2019-02-19T15:23:16 [D|app|fa3ed186] Deface: 'theme_resources' matched 1 times with 'head'
2019-02-19T15:23:16 [I|app|fa3ed186] Deface: [WARNING] No :original defined for 'theme_resources', you should change its definition to include:
2019-02-19T15:23:16 [I|app|fa3ed186] Rendering layouts/base.html.erb
2019-02-19T15:23:16 [I|app|fa3ed186] Rendered layouts/base.html.erb (46.7ms)
2019-02-19T15:23:16 [D|app|fa3ed186] Current location set to none
2019-02-19T15:23:16 [D|app|fa3ed186] Current organization set to MyOrg
2019-02-19T15:23:16 [I|app|fa3ed186] Completed 200 OK in 2571ms (Views: 1063.7ms | ActiveRecord: 212.2ms)