In this specific case, the network range 200-255 is dedicated for leases, so provisioning hosts with IPs in that range wouldn't really be a proper solution.

With that being said, creating a host with it's lease IP as the reservation works fine, but it will give the exact same error if you then try to change it over to a proper IP while the lease record is still in effect.

I imagine that the same issue would also occur if you were to turn an unmanaged host with a leased IP into a managed one with a different reserved address.

While not the same situation, I'm having a similar issue with 1.15

I assign a host with a manual host creation, I then decide I want to delete that host as I want to change some of the parameters on it and hit "delete"
The host fails to delete complaining it can't remove the dhcp entry for this host via the smart proxy.

The logs show something similar to the above situation/error

W, [2017-05-24T08:56:41.768444 ] WARN -- : DELETE dhcp/:network/:record endpoint has been deprecated and will be removed in future versions. Please use DELETE dhcp/:network/mac/:mac_address or DELETE dhcp/:network/ip/:ip_address instead.
E, [2017-05-24T08:56:41.768715 ] ERROR -- : 10.11.216.199 / 00:15:17:a9:e3:48 is static - unable to delete
I, [2017-05-24T08:56:41.768956 ] INFO -- : 10.11.216.4 - - [24/May/2017:08:56:41 +0000] "DELETE /dhcp/10.11.216.0/00:15:17:a9:e3:48 HTTP/1.1" 400 62 0.0007

I, [2017-05-24T08:57:26.755337 ] INFO -- : 10.11.216.4 - - [24/May/2017:08:57:26 +0000] "GET /tftp/serverName HTTP/1.1" 200 17 0.0004

I, [2017-05-24T08:57:26.826435 ] INFO -- : 10.11.216.4 - - [24/May/2017:08:57:26 +0000] "GET /dhcp/10.11.216.0/mac/00:15:17:a9:e3:48 HTTP/1.1" 200 207 0.0005

While not the same situation I thought it maybe useful to share a variation of the situation generating the same error.

Reproduced with develop today where we have improved orchestration logging so it's more clear what is going on.

 INFO  app : Started GET "/discovered_hosts/mac525400130513/edit?utf8=%E2%9C%93&host%5Bhostgroup_id%5D=4&host%5Borganization_id%5D=1&host%5Blocation_id%5D=2&quick_submit=Quick+Create" for 127.0.0.1 at 20
 INFO  app : Processing by DiscoveredHostsController#edit as HTML
 INFO  app :   Parameters: {"utf8"=>"✓", "host"=>{"hostgroup_id"=>"4", "organization_id"=>"1", "location_id"=>"2"}, "quick_submit"=>"Quick Create", "id"=>"mac525400130513"}
 INFO  app : Current user: admin (administrator)
DEBUG  app : Setting current user thread-local variable to admin
DEBUG  app : Setting current organization thread-local variable to none
DEBUG  app : Setting current location thread-local variable to none
DEBUG  app : Setting current organization thread-local variable to none
DEBUG  app : Setting current location thread-local variable to none
DEBUG  app : Comparing ["52:54:00:13:05:13", "192.168.122.6", "192.168.122.0"] == ["52:54:00:13:05:13", "192.168.122.6", "192.168.122.0"]
DEBUG  app : Comparing ["52:54:00:13:05:13", "192.168.122.6", "192.168.122.0"] == ["52:54:00:13:05:13", "192.168.122.6", "192.168.122.0"]
DEBUG  app : Detected a changed required for DHCP record
DEBUG  app : Enqueued task 'Create DHCP Settings for mac525400130513.local.lan' to 'Host::Managed Main' queue
DEBUG  app : Setting current organization thread-local variable to MyOrg
DEBUG  app : Setting current location thread-local variable to MyLoc
DEBUG  app : Setting current location thread-local variable to none
DEBUG  app : Setting current organization thread-local variable to none
DEBUG  app : Enqueued task 'Deploy TFTP PXEGrub2 config for mac525400130513.local.lan' to 'Host::Managed Main' queue
DEBUG  app : Enqueued task 'Deploy TFTP PXELinux config for mac525400130513.local.lan' to 'Host::Managed Main' queue
DEBUG  app : Enqueued task 'Deploy TFTP PXEGrub config for mac525400130513.local.lan' to 'Host::Managed Main' queue
DEBUG  app : Enqueued task 'Fetch TFTP boot files for mac525400130513.local.lan' to 'Host::Managed Main' queue
DEBUG  app : Enqueued task 'Rebooting mac525400130513.local.lan' to 'Host::Managed Post' queue
DEBUG  app : Processing task 'Create DHCP Settings for mac525400130513.local.lan' from 'Host::Managed Main'
 INFO  app : Create DHCP reservation mac525400130513.local.lan for mac525400130513.local.lan-52:54:00:13:05:13/192.168.122.6
DEBUG  app : DHCP reservation on net 192.168.122.0 with attrs: {:hostname=>"mac525400130513.local.lan", :mac=>"52:54:00:13:05:13", :ip=>"192.168.122.6", :network=>"192.168.122.0", :nextServer=>"192.168.1
 WARN  app : Create DHCP Settings for mac525400130513.local.lan task failed with the following error: ERF12-6899 [ProxyAPI::ProxyException]: Unable to set DHCP entry ([RestClient::Conflict]: 409 Conflict
ProxyAPI::ProxyException: ERF12-6899 [ProxyAPI::ProxyException]: Unable to set DHCP entry ([RestClient::Conflict]: 409 Conflict) for proxy http://localhost:8448/dhcp

I only had one lease as expected:

{
    "reservations": [

    ],
    "leases": [
        {
            "name": "*lease*",
            "ip": "192.168.122.6",
            "mac": "52:54:00:13:05:13",
            "subnet": "192.168.122.0/255.255.255.0",
            "starts": "2017-05-24 10:01:35 UTC",
            "ends": "2017-05-24 10:11:35 UTC",
            "state": "active",
            "cltt": "2017-05-24 10:01:35 UTC",
            "next_state": "free",
            "hardware_type": "ethernet" 
        }
    ]
}

On proxy it really treats it as a conflict:

W, [2017-05-24T12:06:08.245118 ]  WARN -- : Request to create a conflicting DHCP record
D, [2017-05-24T12:06:08.245220 ] DEBUG -- : request: #<Proxy::DHCP::Reservation:0x005577770bb410 @name="mac525400130513.local.lan", @subnet=#<Proxy::DHCP::Subnet:0x0055777631ba80 @network="192.168.122.0", @netmask="255.255.255.0", @ipaddr=#<IPAddr: IPv4:192.168.122.0/255.255.255.0>, @options={:routers=>["192.168.122.1"], :domain_name_servers=>["192.168.122.1"]}, @netmask_to_i=4294967040>, @ip="192.168.122.6", @mac="52:54:00:13:05:13", @options={"nextServer"=>"192.168.122.1", "filename"=>"pxelinux.0", "hostname"=>"mac525400130513.local.lan"}>
D, [2017-05-24T12:06:08.245314 ] DEBUG -- : existing: [#<Proxy::DHCP::Lease:0x0055777748dac0 @name="*lease*", @starts=2017-05-24 10:05:25 UTC, @ends=2017-05-24 10:15:25 UTC, @state="active", @subnet=#<Proxy::DHCP::Subnet:0x0055777631ba80 @network="192.168.122.0", @netmask="255.255.255.0", @ipaddr=#<IPAddr: IPv4:192.168.122.0/255.255.255.0>, @options={:routers=>["192.168.122.1"], :domain_name_servers=>["192.168.122.1"]}, @netmask_to_i=4294967040>, @ip="192.168.122.6", @mac="52:54:00:13:05:13", @options={:cltt=>2017-05-24 10:05:25 UTC, :next_state=>"free", :hardware_type=>"ethernet"}>]
E, [2017-05-24T12:06:08.245448 ] ERROR -- : Record 192.168.122.0/192.168.122.6 already exists
D, [2017-05-24T12:06:08.245471 ] DEBUG -- : Record 192.168.122.0/192.168.122.6 already exists (Proxy::DHCP::Collision)

There were some changes previously in proxy, I will ask Dmitri.

Reproducer from comment 5 fails with Smart Proxy 1.15 but works just fine with 1.14, I have just verified this so it is a regression.

Before I split this into two issues, Alex can you please give me more details about your workflow?

- What exactly are you setting during discovery provisioning? Hostname changing? IP? Subnet?
- Is this Auto discovery, Quick discovery or regular Edit Host provisioning?
- Enable debug and pastebin whole production.log transactions, there should be IP/MAC comparison log messages that's the most interesting.

Thanks.

I am able to reproduce it this way:

1) Discovered a host
2) Provision it via form, I change IP address to a different (free) one from the range
3) Foreman now attempts to DELETE lease but leases are not deletable, this was a change introduced in smart-proxy 1.15 and I think something to do with #19649

 INFO  app : Delete DHCP reservation *lease* for -52:54:00:13:05:13/192.168.122.6
 WARN  app : DHCP conflicts removal for mac525400130513.local.lan task failed with the following error: ERF12-0635 [ProxyAPI::ProxyException]: Unable to delete DHCP entry for 52:54:00:13:05:13

This should be reproducable with Foreman Core:

• Create a subnet and unset DHCP Smart Proxy
• Create a host with static IP allocation for that Subnet
• Turn the host on to make sure there is a valid lease
• Edit the subnet and set DHCP Smart Proxy
• Edit the host and change the host IP address

Foreman should identify that the record is a lease and not attempt to delete that record from DHCP, just creating a new one. This is quite artificial scenario, but in discovery this is exactly what is going on.

Lukas Zapletal wrote:

Before I split this into two issues, Alex can you please give me more details about your workflow?

- What exactly are you setting during discovery provisioning? Hostname changing? IP? Subnet?

When provisioning the host from the discovered entry; Host group is set, hostname is changed, domain is changed, and IP is changed - for both IPv4 and IPv6. Additionally an owner is assigned and a PXE loader is chosen.

- Is this Auto discovery, Quick discovery or regular Edit Host provisioning?

Ran into this issue first with quick provisioning - when editing the created host, but reported it with data from a host that was attempted to be created through regular Edit Host provisioning.
Needless to say, that host creation failed.

- Enable debug and pastebin whole production.log transactions, there should be IP/MAC comparison log messages that's the most interesting.

Here you go, the entire transaction for the host creation;
https://pastebin.com/yc7epYq9

I'm not quite sure what more data I could provide that would be of any help, the debug log seems to contain all of the important stuff.

Any reason why the colliding lease couldn't be released during the reservation orchestration? Just lacking proxy support for doing that action?

Root cause is in smart-proxy 1.15 change, leases now always contains "dummy" hostname "*lease*" or "lease-MAC" depending on 1.15 or develop:

[lzap@lzapx smart-proxy]$ curl-proxy /dhcp/192.168.122.0
{
    "reservations": [

    ],
    "leases": [
        {
            "name": "lease-525400130513",
            "ip": "192.168.122.6",
            "mac": "52:54:00:13:05:13",
            "subnet": "192.168.122.0/255.255.255.0",
            "starts": "2017-05-24 12:48:43 UTC",
            "ends": "2017-05-24 12:58:43 UTC",
            "state": "active",
            "next_state": "free" 
        }
    ]
}

Smart-Proxy 1.15:

[lzap@lzapx smart-proxy]$ curl-proxy /dhcp/192.168.122.0/192.168.122.6
{
    "hostname": "lease-525400130513",
    "ip": "192.168.122.6",
    "mac": "52:54:00:13:05:13" 
}

Smart-Proxy 1.14:

[lzap@lzapx smart-proxy]$ curl-proxy /dhcp/192.168.122.0/192.168.122.6
{
    "starts": "2017-05-24 12:52:59 UTC",
    "ends": "2017-05-24 13:02:59 UTC",
    "state": "active",
    "next_state": "free",
    "mac": "52:54:00:13:05:13",
    "subnet": "192.168.122.0/255.255.255.0",
    "ip": "192.168.122.6" 
}

Since Foreman core does a dumb comparison of records based on hostname, this is a conflict now:

    def ==(other)
      return false unless other.present?
      to_compare = [:mac, :ip, :network]

      # If we're converting an 'ad-hoc' lease created by a host booting outside of Foreman's knowledge,
      # then :hostname will be blank on the incoming lease - if the ip/mac still match, then this
      # isn't a conflict.
      to_compare << :hostname if other.attrs[:hostname].present? && attrs[:hostname].present?

      # Not all DHCP smart-proxy providers support TFTP filename option (e.g. libvirt).
      to_compare << :filename if other.attrs[:filename].present? && attrs[:filename].present?

      logger.debug "Comparing #{attrs.values_at(*to_compare)} == #{other.attrs.values_at(*to_compare)}" 
      attrs.values_at(*to_compare) == other.attrs.values_at(*to_compare)
    end

I think the proper solution is to add "type" to records coming out from proxy of either "lease" or "reservation" and use that flag in Foreman to ignore DHCP conflict if any of the two compared records are lease.

Alex, can you try this small patch if it fixes your issue:

https://github.com/theforeman/smart-proxy/pull/532

So, when did this restriction appear?

The infrastructure in place here has been used for quite a while after all, and we've provisioned discovered hosts on it before updating to 1.15.

Until https://github.com/theforeman/foreman/pull/4555 is merged you can try to hotfix your instance with that patch. Please make a comment if it works or not in the PR. I will get back to it next week.

Thanks! It worked like a charm. The failure is gone.

However, I don't really understand proxy logs. Now the "successful" DELETE is gone compared to the previous buggy run posted above.

I, [2017-09-15T13:31:48.002761 ]  INFO -- : 192.168.108.1 - - [15/Sep/2017:13:31:48 +0200] "GET /dhcp/192.168.108.0/mac/00:50:56:b6:e1:35 HTTP/1.1" 200 237 0.0017
E, [2017-09-15T13:31:48.097271 ] ERROR -- : No DHCP records for IP 192.168.108.0/192.168.108.99 found
I, [2017-09-15T13:31:48.097634 ]  INFO -- : 192.168.108.1 - - [15/Sep/2017:13:31:48 +0200] "GET /dhcp/192.168.108.0/ip/192.168.108.99 HTTP/1.1" 404 57 0.0009
I, [2017-09-15T13:31:48.173489 ]  INFO -- : 192.168.108.1 - - [15/Sep/2017:13:31:48 +0200] "GET /dhcp/192.168.108.0/mac/00:50:56:b6:e1:35 HTTP/1.1" 200 237 0.0008
E, [2017-09-15T13:31:48.252719 ] ERROR -- : No DHCP records for IP 192.168.108.0/192.168.108.99 found
I, [2017-09-15T13:31:48.253307 ]  INFO -- : 192.168.108.1 - - [15/Sep/2017:13:31:48 +0200] "GET /dhcp/192.168.108.0/ip/192.168.108.99 HTTP/1.1" 404 57 0.0015
I, [2017-09-15T13:31:53.001487 ]  INFO -- : 192.168.108.1 - - [15/Sep/2017:13:31:53 +0200] "GET /dhcp/192.168.108.0/mac/00:50:56:b6:e1:35 HTTP/1.1" 200 237 0.0014
E, [2017-09-15T13:31:53.072521 ] ERROR -- : No DHCP records for IP 192.168.108.0/192.168.108.99 found
I, [2017-09-15T13:31:53.072815 ]  INFO -- : 192.168.108.1 - - [15/Sep/2017:13:31:53 +0200] "GET /dhcp/192.168.108.0/ip/192.168.108.99 HTTP/1.1" 404 57 0.0010
I, [2017-09-15T13:31:53.222508 ]  INFO -- : 192.168.108.1 - - [15/Sep/2017:13:31:53 +0200] "GET /dhcp/192.168.108.0/mac/00:50:56:b6:e1:35 HTTP/1.1" 200 237 0.0013
E, [2017-09-15T13:31:53.292103 ] ERROR -- : No DHCP records for IP 192.168.108.0/192.168.108.99 found
I, [2017-09-15T13:31:53.292674 ]  INFO -- : 192.168.108.1 - - [15/Sep/2017:13:31:53 +0200] "GET /dhcp/192.168.108.0/ip/192.168.108.99 HTTP/1.1" 404 57 0.0014
W, [2017-09-15T13:31:53.362282 ]  WARN -- : DELETE dhcp/:network/:record endpoint has been deprecated and will be removed in future versions. Please use DELETE dhcp/:network/mac/:mac_address or DELETE dhcp/:network/ip/:ip_address instead.
E, [2017-09-15T13:31:53.362559 ] ERROR -- : 192.168.108.200 / 00:50:56:b6:e1:35 is static - unable to delete
I, [2017-09-15T13:31:53.362918 ]  INFO -- : 192.168.108.1 - - [15/Sep/2017:13:31:53 +0200] "DELETE /dhcp/192.168.108.0/00:50:56:b6:e1:35 HTTP/1.1" 400 64 0.0008
I, [2017-09-15T16:59:01.048311 ]  INFO -- : 192.168.108.1 - - [15/Sep/2017:16:59:01 +0200] "GET /dhcp/192.168.108.0/mac/00:50:56:b6:e1:35 HTTP/1.1" 200 237 0.0013
E, [2017-09-15T16:59:01.119555 ] ERROR -- : No DHCP records for IP 192.168.108.0/192.168.108.99 found
I, [2017-09-15T16:59:01.120074 ]  INFO -- : 192.168.108.1 - - [15/Sep/2017:16:59:01 +0200] "GET /dhcp/192.168.108.0/ip/192.168.108.99 HTTP/1.1" 404 57 0.0012
I, [2017-09-15T16:59:01.427066 ]  INFO -- : 192.168.108.1 - - [15/Sep/2017:16:59:01 +0200] "POST /dhcp/192.168.108.0 HTTP/1.1" 200 - 0.0801

I like when things work but I like it more when things make sense to me. Anyway, thanks for help. I will comment on the PR now.