Bug 1459644 - Getting DHCP conflicts while creating multiple hosts at same time via REST API
Getting DHCP conflicts while creating multiple hosts at same time via REST API
Status: ON_QA
Product: Red Hat Satellite 6
Classification: Red Hat
Component: DHCP & DNS (Show other bugs)
6.2.9
All Linux
medium Severity medium (vote)
: GA
: --
Assigned To: Dmitri Dolguikh
Roman Plevka
: Triaged
Depends On: 1514885
Blocks: 1472891
  Show dependency treegraph
 
Reported: 2017-06-07 13:08 EDT by Nithin Thomas
Modified: 2018-01-08 09:55 EST (History)
16 users (show)

See Also:
Fixed In Version: foreman-proxy-1.15.6.1
Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of:
: 1472891 (view as bug list)
Environment:
Last Closed:
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)


External Trackers
Tracker ID Priority Status Summary Last Updated
Foreman Issue Tracker 20173 None None None 2017-08-08 05:10 EDT
Foreman Issue Tracker 20474 None None None 2017-08-08 10:20 EDT

  None (edit)
Description Nithin Thomas 2017-06-07 13:08:12 EDT
Description of problem:

Customer getting the following error while building multiple hosts at the same time:

Error Message:

"DHCP records xxxx31174.idm.xxx.xxx.com-14:02:ec:86:8d:0c/10.91.241.31 already exists"

Version-Release number of selected component (if applicable):

satellite 6.2

How reproducible:

Always

Steps to Reproduce:

1. Use REST API to create multiple hosts at same time
   HTTP  POST to https://satellite.server.com/api/v2/hosts


Actual results:

Error Message:

"DHCP records xxxx31174.idm.xxx.xxx.com-14:02:ec:86:8d:0c/10.91.241.31 already exists"

Expected results:

Hosts created successfully.

Additional info:

Customer added a 5-second delay in the DHCP API call before it moves on to the build and that seems to be a workaround to the issue.
Comment 5 Lukas Zapletal 2017-06-10 06:08:17 EDT
Hello,

foreman-proxy process keeps track of unused IPs which were handled over to Satellite, this is kept in temp files:

cat /tmp/foreman-proxy_192.168.220.0_24.tmp
56

This mechanism works, but if there are not enough free IP addresses it will cycle in DHCP range configured in dhcpd.conf for that subnet which can lead to conflicts.

Make sure you have enough free IPs in the give range. Check the temp file. I am unable to reproduce, can you attach proxy.log with debug turned on of a whole transaction which leads to conflict? Also attach information about which IP address caused the conflict, so we can track how free IPs were searched.

In general, to prevent this error make sure you use B or A class subnets with many free IPs for this kind of mass-creation.
Comment 11 Dmitri Dolguikh 2017-06-30 06:37:21 EDT
Created an upstream issue: http://projects.theforeman.org/issues/20173
Comment 12 Lukas Zapletal 2017-06-30 07:36:05 EDT
Ok Dmitri found the race condition in the code, I thought Webrick is single threaded but that's not the case anymore. We have a patch, see the PR above.

Since there is an easy workaround to slower down queries, I am setting this as 6.3 bug. If this needs to be backported create new BZ with 6.2.z flag.
Comment 13 Ivan Necas 2017-08-08 05:10:10 EDT
Connecting redmine issue http://projects.theforeman.org/issues/20173 from this bug
Comment 14 Lukas Zapletal 2017-08-08 10:20:48 EDT
Ivan, there are two issues actually. One in Proxy which was fixed by Dmitri, the other one in Foreman core which I am currently working on: 

http://projects.theforeman.org/issues/20474
Comment 16 Lukas Zapletal 2017-08-09 02:47:50 EDT
I plan to work on this, but haven't started yet. So perhaps NEW would be more appropriate, but I am not moving because the bot will change this anyway to POST.

That's right its two commits, both in proxy. There is another one in core but it is irrelevant (randomizing DB IPAM).
Comment 17 pm-sat@redhat.com 2017-09-07 18:01:47 EDT
Upstream bug assigned to ddolguik@redhat.com
Comment 18 pm-sat@redhat.com 2017-09-07 18:01:53 EDT
Upstream bug assigned to ddolguik@redhat.com
Comment 19 pm-sat@redhat.com 2017-11-03 06:02:20 EDT
Moving this bug to POST for triage into Satellite 6 since the upstream issue http://projects.theforeman.org/issues/20474 has been resolved.
Comment 20 Roman Plevka 2017-11-19 11:40:50 EST
Failed QA:

I believe something went wrong with 
https://github.com/theforeman/smart-proxy/pull/543
as this is now causing a regression:


- the calls to proxy:9090/unused_ip made by satellite now exit with err 400:
wrong number of arguments (4 for 3)

(this happens on e.g. creating host)

The request looks like the following:
/dhcp/192.168.100.0/unused_ip?mac=de:ad:be:ef:fe:ed&from=192.168.100.10&to=192.168.100.254


the full traceback with the actual request and its parameters are:


D, [2017-11-19T11:26:35.038302 ] DEBUG -- : accept: 10.16.69.103:55582
D, [2017-11-19T11:26:35.039853 ] DEBUG -- : Rack::Handler::WEBrick is invoked.
D, [2017-11-19T11:26:35.041028 ] DEBUG -- : verifying remote client 10.16.69.103 against trusted_hosts ["blah.blah.com"]
E, [2017-11-19T11:26:35.041834 ] ERROR -- : wrong number of arguments (4 for 3)
D, [2017-11-19T11:26:35.041885 ] DEBUG -- : wrong number of arguments (4 for 3) (ArgumentError)
/usr/share/foreman-proxy/modules/dhcp_common/free_ips.rb:54:in `find_free_ip'
/usr/share/foreman-proxy/modules/dhcp_common/server.rb:99:in `unused_ip'
/usr/share/foreman-proxy/modules/dhcp/dhcp_api.rb:34:in `block in <class:DhcpApi>'
/usr/share/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:1611:in `call'
/usr/share/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:1611:in `block in compile!'
/usr/share/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:975:in `[]'
/usr/share/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:975:in `block (3 levels) in route!'
/usr/share/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:994:in `route_eval'
/usr/share/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:975:in `block (2 levels) in route!'
/usr/share/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:1015:in `block in process_route'
/usr/share/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:1013:in `catch'
/usr/share/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:1013:in `process_route'
/usr/share/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:973:in `block in route!'
/usr/share/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:972:in `each'
/usr/share/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:972:in `route!'
/usr/share/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:1085:in `block in dispatch!'
/usr/share/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:1067:in `block in invoke'
/usr/share/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:1067:in `catch'
/usr/share/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:1067:in `invoke'
/usr/share/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:1082:in `dispatch!'
/usr/share/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:907:in `block in call!'
/usr/share/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:1067:in `block in invoke'
/usr/share/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:1067:in `catch'
/usr/share/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:1067:in `invoke'
/usr/share/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:907:in `call!'
/usr/share/gems/gems/sinatra-1.4.7/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.7/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.7/lib/sinatra/show_exceptions.rb:25:in `call'
/usr/share/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:182:in `call'
/usr/share/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:2013:in `call'
/usr/share/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:1487:in `block in call'
/usr/share/gems/gems/sinatra-1.4.7/lib/sinatra/base.rb:1787:in `synchronize'
/usr/share/gems/gems/sinatra-1.4.7/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'


I, [2017-11-19T11:26:35.042308 ]  INFO -- : 10.16.69.103 - - [19/Nov/2017:11:26:35 -0500] "GET /dhcp/192.168.100.0/unused_ip?mac=de:ad:be:ef:fe:ed&from=192.168.100.10&to=192.168.100.254 HTTP/1.1" 400 35 0.0015

D, [2017-11-19T11:26:35.082673 ] DEBUG -- : close: 10.16.69.103:55582
Comment 21 Ivan Necas 2017-11-20 09:00:49 EST
Dmitri: this looks like a regression, that seems to be also in upstream, introduced by https://github.com/theforeman/smart-proxy/commit/54f44d807b8540fd3561a0d16ab68c68deb88c0f - different number of args for the find_free_ip method. Could you have a look?
Comment 22 Lukas Zapletal 2017-11-20 10:03:35 EST
These two bugs are dupe, I will let Dmitri and QAs to decide which one to close as a dupe:

https://bugzilla.redhat.com/show_bug.cgi?id=1514885
https://bugzilla.redhat.com/show_bug.cgi?id=1459644
Comment 23 Dmitri Dolguikh 2017-11-20 15:38:40 EST
This bug is separate from https://bugzilla.redhat.com/show_bug.cgi?id=1459644 AND is tracked separately upstream, I think this warrants a dedicated BZ.
Comment 24 Ivan Necas 2017-11-21 10:09:12 EST
The fix for wrong number of arguments (4 for 3) is tracked under http://projects.theforeman.org/issues/21710/
Comment 25 Ivan Necas 2017-11-24 04:56:15 EST
Putting to modified, as https://bugzilla.redhat.com/show_bug.cgi?id=1514885, that blocks this BZ was moved to Modified as well: once that one in ON_QA, we can move this one as well

Note You need to log in before you can comment on or make changes to this bug.