Bug #19634

DHCP lease removal leads to error

Added by Alexander Olofsson 6 months ago. Updated about 1 month ago.

Status:Closed
Priority:High
Assigned To:Lukas Zapletal
Category:DHCP
Target version:-
Difficulty: Bugzilla link:
Found in release:1.15.0 Pull request:https://github.com/theforeman/foreman/pull/4555
Story points-
Velocity based estimate-
Release1.15.5Release relationshipAuto

Description

Foreman v1.15.0, Smart Proxy v1.15.0

Attempting to provision a discovered host - which has received a DHCP lease as part of the discovery - fails with the following error;

Unable to save
DHCP conflicts removal for machine.example.com task failed with the following error: ERF12-0635 [ProxyAPI::ProxyException]: Unable to delete DHCP entry for 00:24:81:e1:06:27 ([RestClient::BadRequest]: 400 Bad Request)

The smart-proxy log meanwhile shows the failed attempt as the following messages and backtrace;

W, [2017-05-23T14:04:57.684136 ]  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-23T14:04:57.684508 ] ERROR -- : 10.236.252.204 / 00:24:81:e1:06:27 is static - unable to delete
I, [2017-05-23T14:04:57.685050 ]  INFO -- : 10.236.252.20 - - [23/May/2017:14:04:57 +0200] "DELETE /dhcp/10.236.252.0/00:24:81:e1:06:27 HTTP/1.1" 400 64 0.0013

/usr/share/foreman-proxy/modules/dhcp_common/isc/omapi_provider.rb:19:in `del_record'
/usr/share/foreman-proxy/modules/dhcp/dhcp_api.rb:114:in `block in <class:DhcpApi>'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:1611:in `call'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:1611:in `block in compile!'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:975:in `[]'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:975:in `block (3 levels) in route!'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:994:in `route_eval'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:975:in `block (2 levels) in route!'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:1015:in `block in process_route'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:1013:in `catch'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:1013:in `process_route'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:973:in `block in route!'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:972:in `each'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:972:in `route!'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:1085:in `block in dispatch!'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:1067:in `block in invoke'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:1067:in `catch'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:1067:in `invoke'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:1082:in `dispatch!'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:907:in `block in call!'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:1067:in `block in invoke'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:1067:in `catch'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:1067:in `invoke'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:907:in `call!'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:895:in `call'
/usr/share/gems/gems/rack-1.6.4/lib/rack/methodoverride.rb:22:in `call'
/usr/share/gems/gems/rack-1.6.4/lib/rack/commonlogger.rb:33:in `call'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:219:in `call'
/usr/share/foreman-proxy/lib/proxy/log.rb:109:in `call'
/usr/share/foreman-proxy/lib/proxy/request_id_middleware.rb:9:in `call'
/usr/share/gems/gems/rack-protection-1.5.3/lib/rack/protection/xss_header.rb:18:in `call'
/usr/share/gems/gems/rack-protection-1.5.3/lib/rack/protection/path_traversal.rb:16:in `call'
/usr/share/gems/gems/rack-protection-1.5.3/lib/rack/protection/json_csrf.rb:18:in `call'
/usr/share/gems/gems/rack-protection-1.5.3/lib/rack/protection/base.rb:49:in `call'
/usr/share/gems/gems/rack-protection-1.5.3/lib/rack/protection/base.rb:49:in `call'
/usr/share/gems/gems/rack-protection-1.5.3/lib/rack/protection/frame_options.rb:31:in `call'
/usr/share/gems/gems/rack-1.6.4/lib/rack/nulllogger.rb:9:in `call'
/usr/share/gems/gems/rack-1.6.4/lib/rack/head.rb:13:in `call'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/show_exceptions.rb:25:in `call'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:182:in `call'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:2013:in `call'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:1487:in `block in call'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:1787:in `synchronize'
/usr/share/gems/gems/sinatra-1.4.8/lib/sinatra/base.rb:1487:in `call'
/usr/share/gems/gems/rack-1.6.4/lib/rack/urlmap.rb:66:in `block in call'
/usr/share/gems/gems/rack-1.6.4/lib/rack/urlmap.rb:50:in `each'
/usr/share/gems/gems/rack-1.6.4/lib/rack/urlmap.rb:50:in `call'
/usr/share/gems/gems/rack-1.6.4/lib/rack/builder.rb:153:in `call'
/usr/share/gems/gems/rack-1.6.4/lib/rack/handler/webrick.rb:88:in `service'
/usr/share/ruby/webrick/httpserver.rb:138:in `service'
/usr/share/ruby/webrick/httpserver.rb:94:in `run'
/usr/share/ruby/webrick/server.rb:295:in `block in start_thread'

The only data that exists for the host in question is the following lease entry;

lease 10.236.252.204 {
  starts 2 2017/05/23 08:57:32;
  ends 2 2017/05/23 20:57:32;
  cltt 2 2017/05/23 08:57:32;
  binding state active;
  next binding state free;
  rewind binding state free;
  hardware ethernet 00:24:81:e1:06:27;
}


Related issues

Related to Smart Proxy - Bug #19649: DHCP lease prevents reservation creation with the same MA... Closed 05/24/2017
Related to Smart Proxy - Feature #19666: Return record type for DHCP recorts Closed 05/25/2017
Related to Smart Proxy - Refactor #19668: Remove conflicting leases prior reservation creation New 05/25/2017

History

#1 Updated by Dominic Cleal 6 months ago

  • Project changed from Foreman to Discovery

Moving to Discovery for further triage, this doesn't look like a bug in the smart proxy - it isn't possible to delete leases, hence the error. This looks like a genuine conflict for the same MAC address. The only thing I can't tell without the Foreman log is the IP you assigned.

Perhaps ensure the host is created with the IP address 10.236.252.204, so there isn't a conflict for the same MAC address.

I'm not sure what further recommendations or requirements the Discovery project places on IP allocations or DHCP leases, they may be able to advise.

#2 Updated by Alexander Olofsson 6 months ago

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.

#3 Updated by Matt Darcy 6 months ago

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.

#4 Updated by Lukas Zapletal 6 months ago

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.

#5 Updated by Lukas Zapletal 6 months ago

  • Project changed from Discovery to Smart Proxy
  • Subject changed from DHCP (ISC) fails on conflict removal against lease when provisioning discovered host to DHCP lease prevents reservation creation with the same MAC/IP
  • Found in release set to 1.15.0

I reproduced with Foreman Core:

  • Create a subnet with same lease and foreman IP ranges.
  • Have an active lease for particular MAC and IP.
  • Create new host and give it the same MAC address, select the Subnet and note that Foreman assigns the IP address from the lease. This is expected behavior if lease IP address falls into foreman IP range.
  • Submit leads to DHCP conflict.

This might be bug in Rails core or Smart Proxy, I lean towards smart-proxy because it should simply create the reservation, there is no point treating this as a conflict.

#6 Updated by Lukas Zapletal 6 months ago

  • Priority changed from Normal to High

Bumping priority this is Foreman 1.15 discovery blocker because the plugin always keeps the same MAC/IP address (unless user changes this).

#7 Updated by Dominic Cleal 6 months ago

  • Category set to DHCP

Matt, I don't think your report is related at the moment. It would be better for you to file a separate report with full debug logs from both Foreman and the smart proxy so it can be investigated independently.

Lukas, your error is different to the original report. The original report states that Foreman found a DHCP conflict in the lease and attempted to remove it.

Your log shows that no conflict was reported by Foreman, and your error is on creating a new DHCP record (which was deliberately added in #18070). That doesn't necessarily mean they are related, as conflict detection is in a different place in each case.

I don't think changing the bug report to state that it can't create a reservation is useful, as that's not what the original report states.

#8 Updated by Lukas Zapletal 6 months ago

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.

#9 Updated by Lukas Zapletal 6 months ago

  • Project changed from Smart Proxy to Discovery
  • Subject changed from DHCP lease prevents reservation creation with the same MAC/IP to Foreman attempts to delete DHCP lease during discovery provisioning
  • Category changed from DHCP to Discovery plugin

Ok changing it back to the original report, sorry about that. New issue filed as #19649.

Alex I am currently unable to reproduce, please provide me more details about provisioned host and what are you actually changes, what subnets do you have, what IP address it was given and stuff like that. Don't hesitate to create screenshots and attach them here.

#10 Updated by Lukas Zapletal 6 months ago

  • Related to Bug #19649: DHCP lease prevents reservation creation with the same MAC/IP added

#11 Updated by Lukas Zapletal 6 months ago

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.

#12 Updated by Alexander Olofsson 6 months ago

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?

#13 Updated by Lukas Zapletal 6 months ago

  • Target version set to Plugin 9.1.0

Thanks, one more question - can you compare your subnet lease pool and foreman subnet IP range here? I assume they are different, so IP changes. But hostname can also trigger DHCP orchestration.

#14 Updated by Lukas Zapletal 6 months ago

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.

#15 Updated by Lukas Zapletal 6 months ago

  • Related to Feature #19666: Return record type for DHCP recorts added

#16 Updated by Lukas Zapletal 6 months ago

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

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

#17 Updated by Lukas Zapletal 6 months ago

  • Target version deleted (Plugin 9.1.0)

Allright, the patch will not fix this issue. I had an impression this is a regression but it is not so I am taking this off 9.1.

If you change IP address manually and there is a lease, this never worked - Foreman will attempt to delete lease which will fail. There is currently no workaround for that.

#18 Updated by Alexander Olofsson 6 months ago

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.

#19 Updated by Lukas Zapletal 6 months ago

  • Project changed from Discovery to Foreman
  • Subject changed from Foreman attempts to delete DHCP lease during discovery provisioning to Do not treat DHCP leases as conflicting records
  • Category changed from Discovery plugin to DHCP

So moving on to foreman core project, I have a patch that solve this. It depends on #19666 in smart proxy and it does not treat leases as conflicts, because ISC DHCP allows "converting" them to reservations just be performing the host entry creation. Going forward, we will need to change DHCP create API behavior to delete existing leases for plugins which do not support "conversion" like MSDHCP. I created a ticket for that: #19668

#20 Updated by Lukas Zapletal 6 months ago

  • Related to Refactor #19668: Remove conflicting leases prior reservation creation added

#21 Updated by The Foreman Bot 6 months ago

  • Status changed from New to Ready For Testing
  • Assigned To set to Lukas Zapletal
  • Pull request https://github.com/theforeman/foreman/pull/4555 added

#22 Updated by Lukas Zapletal 6 months ago

  • Subject changed from Do not treat DHCP leases as conflicting records to DHCP lease removal leads to error
  • Assigned To deleted (Lukas Zapletal)
  • Pull request deleted (https://github.com/theforeman/foreman/pull/4555)

My patch no 4555 does not solve the described problem, therefore I am also pulling this out to new item #19706.

The problem here is that the recent changes in DHCP API and Foreman handling of 404 no longer ignores problem when DHCP record deletion fails. I think this should be fixed in smart-proxy, so I filed a ticket for that #19668.

#23 Updated by The Foreman Bot 6 months ago

  • Assigned To set to Lukas Zapletal
  • Pull request https://github.com/theforeman/foreman/pull/4555 added

#24 Updated by Lukas Zapletal 6 months ago

  • Status changed from Ready For Testing to New
  • Assigned To deleted (Lukas Zapletal)
  • Pull request deleted (https://github.com/theforeman/foreman/pull/4555)

#25 Updated by The Foreman Bot 6 months ago

  • Status changed from New to Ready For Testing
  • Assigned To set to Lukas Zapletal
  • Pull request https://github.com/theforeman/foreman/pull/4555 added

#26 Updated by Radosław Piliszek 2 months ago

  • Found in release set to 1.15.0

Hey! Any progress on this? We are on Foreman 1.15.3 and this really makes discovery painful to use.

This is a log from trying to change assigned 192.168.108.202 to 192.168.108.99 via the UI:

I, [2017-09-15T09:19:59.510501 ]  INFO -- : 192.168.108.1 - - [15/Sep/2017:09:19:59 +0200] "GET /dhcp/192.168.108.0/mac/00:50:56:b6:e1:35 HTTP/1.1" 200 281 0.0009
E, [2017-09-15T09:19:59.580941 ] ERROR -- : No DHCP records for IP 192.168.108.0/192.168.108.99 found
I, [2017-09-15T09:19:59.581354 ]  INFO -- : 192.168.108.1 - - [15/Sep/2017:09:19:59 +0200] "GET /dhcp/192.168.108.0/ip/192.168.108.99 HTTP/1.1" 404 57 0.0011
I, [2017-09-15T09:19:59.654143 ]  INFO -- : 192.168.108.1 - - [15/Sep/2017:09:19:59 +0200] "GET /dhcp/192.168.108.0/mac/00:50:56:b6:e1:35 HTTP/1.1" 200 281 0.0008
E, [2017-09-15T09:19:59.722731 ] ERROR -- : No DHCP records for IP 192.168.108.0/192.168.108.99 found
I, [2017-09-15T09:19:59.723184 ]  INFO -- : 192.168.108.1 - - [15/Sep/2017:09:19:59 +0200] "GET /dhcp/192.168.108.0/ip/192.168.108.99 HTTP/1.1" 404 57 0.0011
I, [2017-09-15T09:20:07.254670 ]  INFO -- : 192.168.108.1 - - [15/Sep/2017:09:20:07 +0200] "GET /dhcp/192.168.108.0/mac/00:50:56:b6:e1:35 HTTP/1.1" 200 281 0.0007
E, [2017-09-15T09:20:07.330331 ] ERROR -- : No DHCP records for IP 192.168.108.0/192.168.108.99 found
I, [2017-09-15T09:20:07.330788 ]  INFO -- : 192.168.108.1 - - [15/Sep/2017:09:20:07 +0200] "GET /dhcp/192.168.108.0/ip/192.168.108.99 HTTP/1.1" 404 57 0.0011
I, [2017-09-15T09:20:07.623921 ]  INFO -- : 192.168.108.1 - - [15/Sep/2017:09:20:07 +0200] "GET /dhcp/192.168.108.0/mac/00:50:56:b6:e1:35 HTTP/1.1" 200 281 0.0008
E, [2017-09-15T09:20:07.693988 ] ERROR -- : No DHCP records for IP 192.168.108.0/192.168.108.99 found
I, [2017-09-15T09:20:07.694312 ]  INFO -- : 192.168.108.1 - - [15/Sep/2017:09:20:07 +0200] "GET /dhcp/192.168.108.0/ip/192.168.108.99 HTTP/1.1" 404 57 0.0008
W, [2017-09-15T09:20:07.769600 ]  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.
I, [2017-09-15T09:20:07.827265 ]  INFO -- : 192.168.108.1 - - [15/Sep/2017:09:20:07 +0200] "DELETE /dhcp/192.168.108.0/00:50:56:b6:e1:35 HTTP/1.1" 200 - 0.0580
W, [2017-09-15T09:20:07.951875 ]  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-15T09:20:07.952381 ] ERROR -- : 192.168.108.202 / 00:50:56:b6:e1:35 is static - unable to delete
I, [2017-09-15T09:20:07.952963 ]  INFO -- : 192.168.108.1 - - [15/Sep/2017:09:20:07 +0200] "DELETE /dhcp/192.168.108.0/00:50:56:b6:e1:35 HTTP/1.1" 400 64 0.0015
I, [2017-09-15T09:20:08.031991 ]  INFO -- : 192.168.108.1 - - [15/Sep/2017:09:20:08 +0200] "GET /dhcp/192.168.108.0/mac/00:50:56:b6:e1:35 HTTP/1.1" 200 237 0.0010
E, [2017-09-15T09:20:08.108950 ] ERROR -- : No DHCP records for IP 192.168.108.0/192.168.108.99 found
I, [2017-09-15T09:20:08.109395 ]  INFO -- : 192.168.108.1 - - [15/Sep/2017:09:20:08 +0200] "GET /dhcp/192.168.108.0/ip/192.168.108.99 HTTP/1.1" 404 57 0.0011
I, [2017-09-15T09:20:08.223231 ]  INFO -- : 192.168.108.1 - - [15/Sep/2017:09:20:08 +0200] "POST /dhcp/192.168.108.0 HTTP/1.1" 200 - 0.0342

Any way to help you on this? This really should not result in so many logged errors and a failure.

Why does it try to do everything at least twice? Why does the first delete "succeed" and the next fails?

#27 Updated by Lukas Zapletal 2 months ago

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.

#28 Updated by Daniel Lobato Garcia 2 months ago

  • Release set to 1.16.0

#29 Updated by Radosław Piliszek 2 months ago

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.

#30 Updated by Lukas Zapletal about 1 month ago

  • Status changed from Ready For Testing to Closed

This problem was merged int develop and 1.15.5 as well. See #19706 for more details.

#31 Updated by Marek Hulán about 1 month ago

  • Release changed from 1.16.0 to 1.15.5

moving the release per Lukas comment

Also available in: Atom PDF