DHCP failing to add reservation during provisioning

Problem:
Foreman fails to add DHCP reservation during provisioning causing provisioning to fail.

Expected outcome:
DHCP reservation is set and provisioning proceeds.

Foreman and Proxy versions:
Katello 3.5.2
Foreman 1.16.1

Other relevant data:

## /etc/dhcp/dhcpd.conf is readable by foreman-proxy.

# su -s /bin/bash foreman-proxy

bash-4.2$ cat /etc/dhcp/dhcpd.conf
# dhcpd.conf
authoritative;
allow booting;
allow bootp;
ddns-update-style none;

omapi-port 7911;
omapi-key omapi_key;

key omapi_key {
  algorithm HMAC-MD5;
  secret "somesecret";
}

default-lease-time 43200;
max-lease-time 86400;

#option domain-name "domain.internal";
option domain-name-servers 10.x.x.xxx;
option fqdn.no-client-update    on;  # set the "O" and "S" flag bits
option fqdn.rcode2            255;
option pxegrub code 150 = text ;

# Bootfile Handoff
next-server 10.1.105.12;
option architecture code 93 = unsigned integer 16 ;
if option architecture = 00:06 {
  filename "grub2/shim.efi";
} elsif option architecture = 00:07 {
  filename "grub2/shim.efi";
} elsif option architecture = 00:09 {
  filename "grub2/shim.efi";
} else {
  filename "pxelinux.0";
}

log-facility local6;

include "/etc/dhcp/dhcpd.hosts";
# domain.internal
subnet 10.1.105.0 netmask 255.255.255.0 {
  pool
  {
    range 10.1.105.250 10.1.105.253;
  }
  option subnet-mask 255.255.255.0;
  option routers 10.1.105.12;
  option domain-search "domain.internal";
}

## /etc/foreman-proxy/settings.d/dhcp.yml
:enabled: https
:use_provider: dhcp_isc
:server: 127.0.0.1
:subnets: [10.1.47.0/255.255.255.0, 10.5.47.0/255.255.255.0, 10.1.105.0/255.255.255.0]
---

## /etc/foreman-proxy/settings.d/dhcp_isc.yml
:config: /etc/dhcp/dhcpd.conf
:leases: /var/lib/dhcpd/dhcpd.leases
:key_name: omapi_key
:key_secret: somesecret

:omapi_port: 7911

## Permissions in /etc/dhcp/
$ ll /etc/dhcp/
bash: ll: command not found
bash-4.2$ ls -altr /etc/dhcp/
total 44
-rw-r--r--    1 root  root    120 May 15 22:56 dhcpd6.conf
drwxr-xr-x+   2 root  root     37 May 15 22:56 dhclient.d
-rw-r--r--+   1 dhcpd dhcpd    20 May 17 08:49 dhcpd.hosts
-rwxr-xr-x    1 dhcpd dhcpd  1350 Jun  9 11:52 dhcpd.conf
drwxr-x---+   2 root  dhcpd    28 Jun  9 12:10 scripts
drwxr-x---+   7 root  root   4096 Jun  9 12:10 .
drwxr-xr-x+   2 root  root     28 Jun  9 12:10 dhclient-exit-hooks.d
drwxr-xr-x. 129 root  root  12288 Jun  9 12:10 .

## /var/lib/dhcpd/ is readable by foreman-proxy
$ cat /var/lib/dhcpd/dhcpd.leases
# The format of this file is documented in the dhcpd.leases(5) manual page.
# This lease file was written by isc-dhcp-4.2.5

server-duid "\000\001\000\001\"\217\216/\000PV\230\332\350";

## Permissions in /var/lib/dhcpd/dhcpd.leases

$ ls -altr /var/lib/dhcpd/
total 20
-rw-r--r--   1 dhcpd dhcpd    0 May 15 22:56 dhcpd6.leases
drwxr-xr-x. 63 root  root  4096 Jun  1 13:19 ..
-rw-r--r--   1 dhcpd dhcpd  187 Jun  9 12:43 dhcpd.leases~
-rw-r--r--   1 dhcpd dhcpd  187 Jun  9 12:44 dhcpd.leases
drwxr-xr-x+  2 dhcpd dhcpd  138 Jun  9 12:44 .

# curl -kvs --cert /etc/foreman-proxy/foreman_ssl_cert.pem --key /etc/foreman-proxy/foreman_ssl_key.pem --cacert /etc/foreman-proxy/foreman_ssl_ca.pem https://$(hostname):9090/dhcp
* About to connect() to katello port 9090 (#0)
*   Trying 10.1.105.12...
* Connected to katello (10.1.105.12) port 9090 (#0)
* Initializing NSS with certpath: sql:/etc/pki/nssdb
* skipping SSL peer certificate verification
* NSS: client certificate from file
*       subject: CN=katello.domain.internal
*       start date: May 14 04:04:05 2018 GMT
*       expire date: May 14 04:04:05 2023 GMT
*       common name: katello.domain.internal
*       issuer: E=TISS.ToolsMgmt@education.wa.edu.au,CN=puppetca.domain.internal,O=Department of Education,L=Perth,ST=Western Australia,C=AU
* SSL connection using TLS_RSA_WITH_AES_128_GCM_SHA256
* Server certificate:
*       subject: CN=katello.domain.internal
*       start date: May 14 04:04:05 2018 GMT
*       expire date: May 14 04:04:05 2023 GMT
*       common name: katello.domain.internal
*       issuer: E=admin@us.au,CN=puppetca.domain.internal,O=OurORG,L=Perth,ST=Western Australia,C=AU
> GET /dhcp HTTP/1.1
> User-Agent: curl/7.29.0
> Host: katello:9090
> Accept: */*
>
< HTTP/1.1 200 OK
< Content-Type: application/json
< Content-Length: 176
< X-Content-Type-Options: nosniff
< Server:
< Date: Sat, 09 Jun 2018 07:02:01 GMT
< Connection: Keep-Alive
<
* Connection #0 to host katello left intact
[{"network":"10.1.105.0","netmask":"255.255.255.0","options":{"routers":["10.1.105.12"]}},{"network":"10.5.47.0","netmask":"255.255.255.0","options":{"routers":["10.5.47.1"]}}][root@katello foreman]#

## Error in webui during provisioning
Unable to save
Create DHCP Settings for debra-lazusky.domain.internal task failed with the following error: ERF12-6899 [ProxyAPI::ProxyException]: Unable to set DHCP entry ([RestClient::BadRequest]: 400 Bad Request) for proxy https://katello.domain.internal:9090/dhcp

==> /var/log/foreman-proxy/proxy.log <==
D, [2018-06-09T14:32:37.274516 ] DEBUG -- : accept: 10.1.105.12:57954
D, [2018-06-09T14:32:37.276359 ] DEBUG -- : Rack::Handler::WEBrick is invoked.
D, [2018-06-09T14:32:37.280293 d7a75f2a] DEBUG -- : verifying remote client 10.1.105.12 against trusted_hosts ["katello.domain.internal", "puppetca.domain.internal", "e7359svin2503.domain.internal", "foreman.domain.internal", "puppet.domain.internal"]
D, [2018-06-09T14:32:37.284274 d7a75f2a] DEBUG -- : omshell: executed - set name = "debra-lazusky.domain.internal"
D, [2018-06-09T14:32:37.284454 d7a75f2a] DEBUG -- : nil
D, [2018-06-09T14:32:37.284598 d7a75f2a] DEBUG -- : omshell: executed - set ip-address = 10.1.105.250
D, [2018-06-09T14:32:37.284700 d7a75f2a] DEBUG -- : nil
D, [2018-06-09T14:32:37.284814 d7a75f2a] DEBUG -- : omshell: executed - set hardware-address = 00:50:56:98:1b:92
D, [2018-06-09T14:32:37.284900 d7a75f2a] DEBUG -- : nil
D, [2018-06-09T14:32:37.285044 d7a75f2a] DEBUG -- : omshell: executed - set hardware-type = 1
D, [2018-06-09T14:32:37.285153 d7a75f2a] DEBUG -- : nil
D, [2018-06-09T14:32:37.285453 d7a75f2a] DEBUG -- : omshell: executed - set statements = "filename = \"pxelinux.0\"; next-server = 0a:01:69:0c; option host-name = \"debra-lazusky.domain.internal\";"
D, [2018-06-09T14:32:37.285561 d7a75f2a] DEBUG -- : nil
D, [2018-06-09T14:32:37.285679 d7a75f2a] DEBUG -- : omshell: executed - create
D, [2018-06-09T14:32:37.285759 d7a75f2a] DEBUG -- : nil
E, [2018-06-09T14:32:37.302557 d7a75f2a] ERROR -- : Omshell failed:
> > > > obj: <null>
, > obj: host
, > obj: host
, name = "debra-lazusky.domain.internal"
, > obj: host
, name = "debra-lazusky.domain.internal"
, ip-address = 0a:01:69:fa
, > obj: host
, name = "debra-lazusky.domain.internal"
, ip-address = 0a:01:69:fa
, hardware-address = 00:50:56:98:1b:92
, > obj: host
, name = "debra-lazusky.domain.internal"
, ip-address = 0a:01:69:fa
, hardware-address = 00:50:56:98:1b:92
, hardware-type = 1
, > obj: host
, name = "debra-lazusky.domain.internal"
, ip-address = 0a:01:69:fa
, hardware-address = 00:50:56:98:1b:92
, hardware-type = 1
, statements = "filename = "pxelinux.0"; next-server = 0a:01:69:0c; option host-name = "debra-lazusky.domain.internal";"
, > can't open object: connection reset by peer
, obj: host
, name = "debra-lazusky.domain.internal"
, ip-address = 0a:01:69:fa
, hardware-address = 00:50:56:98:1b:92
, hardware-type = 1
, statements = "filename = "pxelinux.0"; next-server = 0a:01:69:0c; option host-name = "debra-lazusky.domain.internal";"
, >
E, [2018-06-09T14:32:37.303182 d7a75f2a] ERROR -- : Failed to add DHCP reservation for debra-lazusky.domain.internal (10.1.105.250 / 00:50:56:98:1b:92)
D, [2018-06-09T14:32:37.303242 d7a75f2a] DEBUG -- : Failed to add DHCP reservation for debra-lazusky.domain.internal (10.1.105.250 / 00:50:56:98:1b:92) (Proxy::DHCP::Error)

## pastebin of full logs during provisioning attempt
https://pastebin.com/raw/kevawUQK

Sorry about the formatting, I can’t edit the post to fix it.

Is this file empty too? The problem is that DHCP daemon is unable to add the reservation, either MAC address, IP or hostname already exist.

Restart DHCP daemon as well, it might have different data in memory than what you see in files.

Hey lzap, cheers. A couple of your other posts have helped out with the config and to eliminate some red herrings I was seeing in the logs.

/etc/dhcp/hosts is empty.

$ cat /etc/dhcp/dhcpd.hosts
# static DHCP hosts

IP suggestion is working and the suggested IP increments with each attempt.

dhcpd is also listening on port 7911

$ netstat -ntlp | grep 7911
tcp 0 0 0.0.0.0:7911 0.0.0.0:* LISTEN 7075/dhcpd

I have dhcpd configured to log to /var/log/dhcpd.log

$ tail /var/log/dhcpd.log
Jun  9 20:40:07 katello dhcpd: DHCPINFORM from 10.5.20.5 via 10.5.20.1: unknown subnet for client address 10.5.20.5
Jun  9 20:45:50 katello dhcpd: DHCPINFORM from 10.5.20.5 via 10.5.20.1: unknown subnet for client address 10.5.20.5
Jun  9 20:46:27 katello dhcpd: Internet Systems Consortium DHCP Server 4.2.5
Jun  9 20:46:27 katello dhcpd: Copyright 2004-2013 Internet Systems Consortium.
Jun  9 20:46:27 katello dhcpd: All rights reserved.
Jun  9 20:46:27 katello dhcpd: For info, please visit https://www.isc.org/software/dhcp/
Jun  9 20:46:27 katello dhcpd: Wrote 0 leases to leases file.
Jun  9 20:46:27 katello dhcpd: Listening on LPF/ens160/00:50:56:98:ef:ac/10.1.105.0/24
Jun  9 20:46:27 katello dhcpd: Sending on   LPF/ens160/00:50:56:98:ef:ac/10.1.105.0/24
Jun  9 20:46:27 katello dhcpd: Sending on   Socket/fallback/fallback-net

I’ve been working at this for a while now and as far as I can tell the config is correct. I must be missing something though.

I restarted dhcpd.service again also. Provisioning fails within a couple of seconds with the same error.

ERF12-6899 [ProxyAPI::ProxyException]: Unable to set DHCP entry ([RestClient::BadRequest]

I see the VM shell created and then deleted in vSphere.

There was a bug fixed in 1.17 and backported into 1.16.1 when DHCP orchestration was done twice. Can you rule out that the HTTP POST on /dhcp is called twice (the sedond one errors out due to conflict)?

Is the current error still the same omapi error? Franky I have never seen this, is proxy managing ISC DHCP on the same server? Any firewalls in between? This looks like the server closed the connection for some reason. Firewall, SELinux, antivirus - three things to check.

I see two POST events, one in proxy.log and one in messages. They could be the same event reported twice?

==> /var/log/foreman-proxy/proxy.log <==
I, [2018-06-10T07:52:34.028252 623c36cf]  INFO -- : 10.1.105.12 - - [10/Jun/2018:07:52:34 +0800] "POST /dhcp/10.1.105.0 HTTP/1.1" 400 103 0.0172

==> /var/log/messages <==
Jun 10 07:52:34 e7359svin2499 daemon.info smart-proxy:katello.domain.internal - - [10/Jun/2018:07:52:34 AWST] "POST /dhcp/10.1.105.0 HTTP/1.1" 400 103
Jun 10 07:52:34 katello daemon.info smart-proxy:- -> /dhcp/10.1.105.0

Yes, no change there.
==> /var/log/foreman-proxy/proxy.log <==
D, [2018-06-10T07:52:34.008870 ] DEBUG – : accept: 10.1.105.12:38626
D, [2018-06-10T07:52:34.010393 ] DEBUG – : Rack::Handler::WEBrick is invoked.
D, [2018-06-10T07:52:34.011493 623c36cf] DEBUG – : verifying remote client 10.1.105.12 against trusted_hosts [“e7359svin2499.resources.internal”, “e7359svin2502.resources.internal”, “e7359svin2503.resources.internal”, “foreman.resources.internal”, “puppet.resources.internal”]
D, [2018-06-10T07:52:34.014437 623c36cf] DEBUG – : omshell: executed - set name = “elmer-girardot.resources.internal”
D, [2018-06-10T07:52:34.014576 623c36cf] DEBUG – : nil
D, [2018-06-10T07:52:34.014665 623c36cf] DEBUG – : omshell: executed - set ip-address = 10.1.105.252
D, [2018-06-10T07:52:34.014721 623c36cf] DEBUG – : nil
D, [2018-06-10T07:52:34.014789 623c36cf] DEBUG – : omshell: executed - set hardware-address = 00:50:56:98:6f:85
D, [2018-06-10T07:52:34.014855 623c36cf] DEBUG – : nil
D, [2018-06-10T07:52:34.014941 623c36cf] DEBUG – : omshell: executed - set hardware-type = 1
D, [2018-06-10T07:52:34.014994 623c36cf] DEBUG – : nil
D, [2018-06-10T07:52:34.015236 623c36cf] DEBUG – : omshell: executed - set statements = “filename = “pxelinux.0”; next-server = 0a:01:69:0c; option host-name = “elmer-girardot.resources.internal”;”
D, [2018-06-10T07:52:34.015308 623c36cf] DEBUG – : nil
D, [2018-06-10T07:52:34.015374 623c36cf] DEBUG – : omshell: executed - create
D, [2018-06-10T07:52:34.015439 623c36cf] DEBUG – : nil
E, [2018-06-10T07:52:34.027231 623c36cf] ERROR – : Omshell failed:
> > > > obj:
, > obj: host
, > obj: host
, name = “elmer-girardot.resources.internal”
, > obj: host
, name = “elmer-girardot.resources.internal”
, ip-address = 0a:01:69:fc
, > obj: host
, name = “elmer-girardot.resources.internal”
, ip-address = 0a:01:69:fc
, hardware-address = 00:50:56:98:6f:85
, > obj: host
, name = “elmer-girardot.resources.internal”
, ip-address = 0a:01:69:fc
, hardware-address = 00:50:56:98:6f:85
, hardware-type = 1
, > obj: host
, name = “elmer-girardot.resources.internal”
, ip-address = 0a:01:69:fc
, hardware-address = 00:50:56:98:6f:85
, hardware-type = 1
, statements = “filename = “pxelinux.0”; next-server = 0a:01:69:0c; option host-name = “elmer-girardot.resources.internal”;”
, > can’t open object: connection reset by peer
, obj: host
, name = “elmer-girardot.resources.internal”
, ip-address = 0a:01:69:fc
, hardware-address = 00:50:56:98:6f:85
, hardware-type = 1
, statements = “filename = “pxelinux.0”; next-server = 0a:01:69:0c; option host-name = “elmer-girardot.resources.internal”;”
, >
E, [2018-06-10T07:52:34.027577 623c36cf] ERROR – : Failed to add DHCP reservation for elmer-girardot.resources.internal (10.1.105.252 / 00:50:56:98:6f:85)
D, [2018-06-10T07:52:34.027629 623c36cf] DEBUG – : Failed to add DHCP reservation for elmer-girardot.resources.internal (10.1.105.252 / 00:50:56:98:6f:85) (Proxy::DHCP::Error)

Glad to know we are special :slight_smile:

katello.domain.internal hosts the ISC DHCP server and the Foreman DHCP Smart Proxy. Our environment does not run DHCP on server VLANS. Rather than configure DHCP for all VLANs I am attempting to set up provisioning VLANs for Prod and Test so each new server will be provisioned in the provisioning VLAN and built with a NIC in it’s target VLAN.

$ hammer proxy info --id 1
Id:            1
Name:          katello.domain.internal
URL:           https://katello.domain.internal:9090
Features:
    Templates
    Pulp
    TFTP
    DNS
    DHCP
    Logs
    Dynflow
    SSH
Locations:
    central_office
Organizations:
    OurORG
Created at:    2018/05/16 09:41:45
Updated at:    2018/05/16 22:44:20

selinux is disabled

$ sestatus
SELinux status:                 disabled

We do not have a local firewall running at this stage. External firewalls shouldn’t be affecting local dhcp requests.

# systemctl status firewalld
* firewalld.service - firewalld - dynamic firewall daemon
   Loaded: loaded (/usr/lib/systemd/system/firewalld.service; disabled; vendor preset: enabled)
   Active: inactive (dead)

No local antivirus at this stage either.
We are running custom SSL certificates for Foreman but I am not seeing any SSL errors.

I have also tried to rule out any issues with the omapi_key by commenting out the related sections of /etc/dhcp/dhcpd.conf and /etc/foreman-proxy/settings.d/dhcp_isc.yml then restarting dhcpd.service and foreman-proxy.service.

Could you confirm that the Komapi_key.+157+xxxxx.key and Komapi_key.+157+xxxxx.private files do not need to be kept somewhere? According to this Red Hat doco they can be deleted once the secret is extracted.

I have done some testing to attempt to verify that omshell is working correctly. I was able to manually create and remove dhcp leases via omshell as both the dhcpd and foreman-proxy users.

$ su -s /bin/bash dhcpd
bash-4.2$ omshell
> key omapi_key somesecret
obj: <null>
> connect
obj: <null>
> new host
obj: host
> set name = "some-host"
obj: host
name = "some-host"
> set ip-address = 10.1.105.251
obj: host
name = "some-host"
ip-address = 0a:01:69:fb
> set hardware-type =1
obj: host
name = "some-host"
ip-address = 0a:01:69:fb
hardware-type = 1
> set hardware-address = 00.56.50.11.22.33
obj: host
name = "some-host"
ip-address = 0a:01:69:fb
hardware-type = 1
hardware-address = 00:38:32:0b:16:21
> create
obj: host
name = "some-host"
ip-address = 0a:01:69:fb
hardware-type = 00:00:00:01
hardware-address = 00:38:32:0b:16:21
>

# cat /var/lib/dhcpd/dhcpd.leases
# The format of this file is documented in the dhcpd.leases(5) manual page.
# This lease file was written by isc-dhcp-4.2.5

host some-host {
  dynamic;
  hardware ethernet 00:38:32:0b:16:21;
  fixed-address 10.1.105.251;
}
server-duid "\000\001\000\001\"\217\216/\000PV\230\332\350";

bash-4.2$ omshell
> key omapi_key somesecret
> connect
obj: <null>
> new host
obj: host
> set name = "some-host"
obj: host
name = "some-host"
> set ip-address = 10.1.105.251
obj: host
name = "some-host"
ip-address = 0a:01:69:fb
> set hardware-type =1
obj: host
name = "some-host"
ip-address = 0a:01:69:fb
hardware-type = 1
> set hardware-address = 00.56.50.11.22.33
obj: host
name = "some-host"
ip-address = 0a:01:69:fb
hardware-type = 1
hardware-address = 00:38:32:0b:16:21
> open
obj: host
name = "some-host"
ip-address = 0a:01:69:fb
hardware-type = 00:00:00:01
hardware-address = 00:38:32:0b:16:21
> remove
obj: <null>
>

$ cat /var/lib/dhcpd/dhcpd.leases
# The format of this file is documented in the dhcpd.leases(5) manual page.
# This lease file was written by isc-dhcp-4.2.5

host some-host {
  dynamic;
  hardware ethernet 00:38:32:0b:16:21;
  fixed-address 10.1.105.251;
}
server-duid "\000\001\000\001\"\217\216/\000PV\230\332\350";

host some-host {
  dynamic;
  deleted;
}

Yes they can be deleted.

Well, this is weird, if you are able to create the records via omapi shell, the smart proxy does exactly the same. However I do see one difference, the stream of commands sent by proxy is: key, server, port, connect, new host. In your paste, I do not see the server command. Can you do the same? The server string is kept in YAML config. Talking to wrong server maybe?

This ended up being a config error on my part. The fact that you has never seen anything like this was making me lean that way. I had rerun foreman-installer after my original post on the weekend with dhcp-manage=false, what I didn’t realise is that this still updates the foreman-proxy dhcp config and the answers file had an old omapi_key secret in it. Once I made sure (again) that dhcpd.conf and dhcp_isc.yml had matching omapi_key secret entries it worked.

This wasn’t the original issue as I checked that the secrets matched with grep before posting and tested with no omapi_key. Thanks for your help, much appreciated.

Weird error for wrong key, feel free to add the message to Troubleshooting - Foreman thanks!