Foreman-proxy Failed to add DHCP reservation for new_vm

h2brvc · January 28, 2022, 12:14pm

Problem:
When creating a new host, the remote foreman-proxy (Ubuntu 3.1.1-1) can’t create a DHCP lease in isc-dhcp-server (4.4.1-2.1ubuntu5.20.04.2) via omapi. If I look in /var/lib/dhcp/dhcpd.leases I can find the just (failed) created DHCP lease as expected.
The Foreman-proxy server was upgraded from 1.24 to 3.1 recently during distribution upgrades. The Foreman server itself can’t be upgraded at this time but will be upgraded in the near future.

Expected outcome:
Create DHCP lease in order to continue VM creation.

Foreman and Proxy versions:
Foreman server:
Foreman = 1.24.3-2

Foreman-proxy server:
Foreman Proxy = 3.1.1-1
isc-dhcp-server = 4.4.1-2.1ubuntu5.20.04.2

Foreman and Proxy plugin versions:
Foreman server: 1.24.3
Foreman proxy: 3.1.1 (proxy, DHCP, DNS, TFTP). Discovery at version 1.0.3.

Distribution and version:
Foreman server: Ubuntu 16.04.7
Foreman-proxy: Ubuntu 20.04.3

Other relevant data:

Foreman-proxy log during the creation of DHCP lease

2022-01-28T12:47:53 20e04c92 [I] Started GET /tftp/serverName
2022-01-28T12:47:53 20e04c92 [I] Finished GET /tftp/serverName with 200 (16.19 ms)
2022-01-28T12:47:53 20e04c92 [I] Started POST /dhcp/10.20.0.0
2022-01-28T12:47:53 20e04c92 [E] Omshell failed: omshell= > > > obj: <null>
omshell= > obj: host
omshell= > obj: host
omshell= name = "new_vm.domain.tld"
omshell= > obj: host
omshell= name = "new_vm.domain.tld"
omshell= ip-address = 0a:14:00:af
omshell= > obj: host
omshell= name = "new_vm.domain.tld"
omshell= ip-address = 0a:14:00:af
omshell= hardware-address = 00:50:56:81:b5:95
omshell= > obj: host
omshell= name = "new_vm.domain.tld"
omshell= ip-address = 0a:14:00:af
omshell= hardware-address = 00:50:56:81:b5:95
omshell= hardware-type = 1
omshell= > obj: host
omshell= name = "new_vm.domain.tld"
omshell= ip-address = 0a:14:00:af
omshell= hardware-address = 00:50:56:81:b5:95
omshell= hardware-type = 1
omshell= statements = "filename = "pxelinux.0"; next-server = 0a:14:00:22; option host-name = "new_vm.domain.tld";"
omshell= > can't open object: connection reset by peer
omshell= obj: host
omshell= name = "new_vm.domain.tld"
omshell= ip-address = 0a:14:00:af
omshell= hardware-address = 00:50:56:81:b5:95
omshell= hardware-type = 1
omshell= statements = "filename = "pxelinux.0"; next-server = 0a:14:00:22; option host-name = "new_vm.domain.tld";"
omshell= >
2022-01-28T12:47:53 20e04c92 [E] Failed to add DHCP reservation for new_vm.domain.tld (10.20.0.175 / 00:50:56:81:b5:95)
2022-01-28T12:47:53 20e04c92 [W] Error details for Failed to add DHCP reservation for new_vm.domain.tld (10.20.0.175 / 00:50:56:81:b5:95): <Proxy::DHCP::Error>: Failed to add DHCP reservation for new_vm.domain.tld (10.20.0.175 / 00:50:56:81:b5:95)
/usr/share/foreman-proxy/modules/dhcp_common/isc/omapi_provider.rb:109:in `report'
/usr/share/foreman-proxy/modules/dhcp_common/isc/omapi_provider.rb:87:in `om_disconnect'
/usr/share/foreman-proxy/modules/dhcp_common/isc/omapi_provider.rb:60:in `om_add_record'
/usr/share/foreman-proxy/modules/dhcp_common/isc/omapi_provider.rb:36:in `add_record'
/usr/share/foreman-proxy/modules/dhcp/dhcp_api.rb:97:in `block in <class:DhcpApi>'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1636:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1636:in `block in compile!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:987:in `block (3 levels) in route!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1006:in `route_eval'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:987:in `block (2 levels) in route!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1035:in `block in process_route'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1033:in `catch'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1033:in `process_route'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:985:in `block in route!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:984:in `each'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:984:in `route!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1098:in `block in dispatch!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1072:in `block in invoke'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1072:in `catch'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1072:in `invoke'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1095:in `dispatch!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:919:in `block in call!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1072:in `block in invoke'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1072:in `catch'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1072:in `invoke'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:919:in `call!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:908:in `call'
/usr/lib/ruby/vendor_ruby/rack/method_override.rb:22:in `call'
/usr/share/foreman-proxy/lib/proxy/log.rb:105:in `call'
/usr/share/foreman-proxy/lib/proxy/request_id_middleware.rb:11:in `call'
/usr/lib/ruby/vendor_ruby/rack/protection/xss_header.rb:18:in `call'
/usr/lib/ruby/vendor_ruby/rack/protection/path_traversal.rb:16:in `call'
/usr/lib/ruby/vendor_ruby/rack/protection/json_csrf.rb:26:in `call'
/usr/lib/ruby/vendor_ruby/rack/protection/base.rb:50:in `call'
/usr/lib/ruby/vendor_ruby/rack/protection/base.rb:50:in `call'
/usr/lib/ruby/vendor_ruby/rack/protection/frame_options.rb:31:in `call'
/usr/lib/ruby/vendor_ruby/rack/null_logger.rb:9:in `call'
/usr/lib/ruby/vendor_ruby/rack/head.rb:12:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/show_exceptions.rb:22:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:194:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1951:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1503:in `block in call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1730:in `synchronize'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1503:in `call'
/usr/lib/ruby/vendor_ruby/rack/urlmap.rb:68:in `block in call'
/usr/lib/ruby/vendor_ruby/rack/urlmap.rb:53:in `each'
/usr/lib/ruby/vendor_ruby/rack/urlmap.rb:53:in `call'
/usr/lib/ruby/vendor_ruby/rack/builder.rb:153:in `call'
/usr/lib/ruby/vendor_ruby/rack/handler/webrick.rb:86:in `service'
/usr/lib/ruby/2.7.0/webrick/httpserver.rb:140:in `service'
/usr/lib/ruby/2.7.0/webrick/httpserver.rb:96:in `run'
/usr/lib/ruby/2.7.0/webrick/server.rb:307:in `block in start_thread'
/usr/lib/ruby/vendor_ruby/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
2022-01-28T12:47:53 20e04c92 [W] Failed to add DHCP reservation for new_vm.domain.tld (10.20.0.175 / 00:50:56:81:b5:95): <Proxy::DHCP::Error>: Failed to add DHCP reservation for new_vm.domain.tld (10.20.0.175 / 00:50:56:81:b5:95)
/usr/share/foreman-proxy/modules/dhcp_common/isc/omapi_provider.rb:109:in `report'
/usr/share/foreman-proxy/modules/dhcp_common/isc/omapi_provider.rb:87:in `om_disconnect'
/usr/share/foreman-proxy/modules/dhcp_common/isc/omapi_provider.rb:60:in `om_add_record'
/usr/share/foreman-proxy/modules/dhcp_common/isc/omapi_provider.rb:36:in `add_record'
/usr/share/foreman-proxy/modules/dhcp/dhcp_api.rb:97:in `block in <class:DhcpApi>'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1636:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1636:in `block in compile!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:987:in `block (3 levels) in route!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1006:in `route_eval'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:987:in `block (2 levels) in route!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1035:in `block in process_route'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1033:in `catch'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1033:in `process_route'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:985:in `block in route!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:984:in `each'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:984:in `route!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1098:in `block in dispatch!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1072:in `block in invoke'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1072:in `catch'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1072:in `invoke'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1095:in `dispatch!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:919:in `block in call!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1072:in `block in invoke'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1072:in `catch'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1072:in `invoke'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:919:in `call!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:908:in `call'
/usr/lib/ruby/vendor_ruby/rack/method_override.rb:22:in `call'
/usr/share/foreman-proxy/lib/proxy/log.rb:105:in `call'
/usr/share/foreman-proxy/lib/proxy/request_id_middleware.rb:11:in `call'
/usr/lib/ruby/vendor_ruby/rack/protection/xss_header.rb:18:in `call'
/usr/lib/ruby/vendor_ruby/rack/protection/path_traversal.rb:16:in `call'
/usr/lib/ruby/vendor_ruby/rack/protection/json_csrf.rb:26:in `call'
/usr/lib/ruby/vendor_ruby/rack/protection/base.rb:50:in `call'
/usr/lib/ruby/vendor_ruby/rack/protection/base.rb:50:in `call'
/usr/lib/ruby/vendor_ruby/rack/protection/frame_options.rb:31:in `call'
/usr/lib/ruby/vendor_ruby/rack/null_logger.rb:9:in `call'
/usr/lib/ruby/vendor_ruby/rack/head.rb:12:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/show_exceptions.rb:22:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:194:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1951:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1503:in `block in call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1730:in `synchronize'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1503:in `call'
/usr/lib/ruby/vendor_ruby/rack/urlmap.rb:68:in `block in call'
/usr/lib/ruby/vendor_ruby/rack/urlmap.rb:53:in `each'
/usr/lib/ruby/vendor_ruby/rack/urlmap.rb:53:in `call'
/usr/lib/ruby/vendor_ruby/rack/builder.rb:153:in `call'
/usr/lib/ruby/vendor_ruby/rack/handler/webrick.rb:86:in `service'
/usr/lib/ruby/2.7.0/webrick/httpserver.rb:140:in `service'
/usr/lib/ruby/2.7.0/webrick/httpserver.rb:96:in `run'
/usr/lib/ruby/2.7.0/webrick/server.rb:307:in `block in start_thread'
/usr/lib/ruby/vendor_ruby/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
2022-01-28T12:47:53 20e04c92 [I] Finished POST /dhcp/10.20.0.0 with 400 (135.07 ms)

lzap · January 28, 2022, 3:00pm

This really looks like something closed the connection from proxy to DHCP server. A firewall perhaps?

Is proxy connecting to ISC DHCP on localhost?

Make sure your proxy and dhcp have both the correct omapi key: DHCP failing to add reservation during provisioning

fgoebel · January 31, 2022, 6:51am

Hello,
I recently stumbled across this as well. This seems like an bug in isc-dhcp-server version 4.4.2 bundled in Ubuntu 20.04.

I was able to build the isc-dhcp-server from sources GitHub - isc-projects/dhcp: ISC DHCP is enterprise grade, open source solution for DHCP servers, relay agents, and clients, supports both IPv4 and IPv6, and is suitable for use in high-volume and high-reliability applications., and dirty make install it over the install of the package to get it working again. But this is really really dirty.

I will rebuild my DHCP-Server-proxy on cent-os soon and hope this will be much more stable.

h2brvc · January 31, 2022, 7:59am

@lzap Firewall hasn’t changed since before the upgrade but I’ll take a look at it just to be sure.
Both Foreman-proxy and isc-dhcp-server are running on the same machine.

@fgoebel, Thanks for your input. I’ll take a look if I can build the DHCP server from source ourselves.

h2brvc · January 31, 2022, 9:11am

Cloned the repo and configured/make the source. After the install I rebooted the foreman-proxy server just to be sure.
Unfortunately I still got the same error (can’t open object: connection reset by peer) while the object is created according to the dhcpd.leases file.

h2brvc · January 31, 2022, 9:45am

Used the mentioned source (Files · master · ISC Open Source Projects / dhcp · GitLab).
After building/installing I had to adjust the systemd startup file after which I could create new VMs via Foreman.

fgoebel · January 31, 2022, 11:23am

Yes, i totally forgot I had adjusted the systemd startup file

To sum all the things i did to get the isc-dhcp-server working with ubuntu20.04 again:

I build the isc-dhcp-server like this:

apt install isc-dhcp-server # yes this is dirtily installed over the package...
apt-mark hold isc-dhcp-server # to not accidentially overwrite this hack

git clone https://github.com/isc-projects/dhcp.git
cd dhcp

./configure --enable-paranoia
make install

This is the line which is used in my current isc-dhcp-server.service file:

exec dhcpd -user dhcpd -group dhcpd -f -4 -pf /run/dhcp-server/dhcpd.pid -lf /var/lib/dhcp/dhcpd.leases -cf $CONFIG_FILE $INTERFACESv4'

When i remember correctly one of the switches -pf or -lf was missing

Please be totally aware that this is a really dirty fix…

lzap · February 1, 2022, 8:52am

Damn that is nasty, isn’t that supposed to be a stable release of Ubuntu?

Could you file a bug for them? That should totally be fixed. Reproducer should be simple, just run omshell and perform these commands manually.

Conzar · February 2, 2022, 11:05pm

I can confirm, I had this problem on Ubuntu 20.04 server. I performed the detailed solution from @fgoebel and provisioning DHCP IPs is now working. Thank you!

fgoebel · February 3, 2022, 4:05pm

I thought the bugs were already there, I added a comment about the ubuntu-bug. I just did not feel that this bug gets much attention from the developers.

lzap · February 16, 2022, 7:49am

The thing is, ISC moved to their new project/product ISC Kea and the original ISD DHCP no longer sees any major development. They want people to migrate to Key, however, Foreman does not support Kea at the moment, at least we do not have official plugin. There might be a 3rd party plugin, check that.

Be aware that Kea has some very important features hidden behind a paywall.

gafferman · March 18, 2022, 7:03pm

Reinstalling isc-dhcp-server from source per @fgoebel’s guidance fixed for me too.
working dhcpd: isc-dhcpd-4.4.2b1
broken dhcpd: isc-dhcpd-4.4.1

Took me a long time to find this topic. Occassionally creating a host works with the packaged version, and intermittent problems can be tough to nail. For completeness, commands post installing the DHCP smart-proxy service are:

sudo systemctl stop isc-dhcp-server
sudo apt-mark hold isc-dhcp-server # to not accidentially overwrite this hack
git clone https://github.com/isc-projects/dhcp.git
cd dhcp
./configure --enable-paranoia
make
sudo make install
sudo sed -i "s/    exec.*/    exec dhcpd -user dhcpd -group dhcpd -f -4 -pf \/run\/dhcp-server\/dhcpd.pid -lf \/var\/lib\/dhcp\/dhcpd.leases -cf \$CONFIG_FILE \$INTERFACESv4'/g" /usr/lib/systemd/system/isc-dhcp-server.service
sudo systemctl daemon-reload
sudo systemctl start isc-dhcp-server

Maybe they’ll ship 22.04 LTS next month with a working package. Until then might be worth documenting how to get foreman proxy working on Ubuntu 20.04

Now to figure why nothing is arriving in my /srv/tftp/pxelinux.cfg …

mfuhrmann · November 2, 2022, 1:55pm

Thanks for documenting this here! Even if I spend a shit ton of time into the troubleshoot, I was happy to find it here.
It looks like my 3.0 proxies are still working with Foreman server 3.2. For now I will keep it as is since I also have problems with the DNS proxy in Windows which are more important to fix.

Stefan_Lasiewski · May 8, 2023, 9:50pm

Thanks for documenting this folks. I also ran into the same problem, and it took forever to figure out what was going on. /usr/bin/omshell on Ubuntu 20.04 is broken, and has been broken for over 2 years. I doubt it will get fixed.

I documented my own steps to workaround this bug at the end of upstream ticket at Bug #1916931 “omshell returns inconsistent results or segfaults” : Bugs : isc-dhcp package : Ubuntu . I simply replaced /usr/bin/omshell with a new version and it seems to work.

mfuhrmann · May 12, 2023, 9:03am

@gafferman Do you know if it works with 22.04?

mfuhrmann · May 12, 2023, 11:36am

It won’t work with U22 since they still offer the old version: https://packages.ubuntu.com/jammy/isc-dhcp-client

Now I’ve went @Stefan_Lasiewski 's way, since I think this might be a workaround with less changes. to find out Foreman does not have repos for Jammy Index of /dists

mfuhrmann · May 12, 2023, 11:38am

Found the issue Foreman on Ubuntu 22.04 Jammy