[Kea-users] Relay not working?

Wed Nov 14 21:34:10 UTC 2018

I'm trying to set up a PXE boot server. DHCP is provided by an existin
g DHCP server on the network, so this server needs to handle PXE boot
options (and apparently needs to handle address assignment as well).
To this end I'm using this DHCP server to set up PXE options and relay
the dhcp request to the upstream DHCP server for address
configuration.

The Kea DHCP server's address i 10.0.132.217. Kea DHCP4 is version
1.1.0 (Ubunt Bionic).
"Dhcp4" {
  "interfaces-config": { "interfaces": [ "*" ] },
  "client-classes": [ { "name": "pxeclient",
# vendor-class-identifier, numeric form
      "test": "substring(option[60].text, 0, 9) == 'PXEClient'",
      "boot-file-name": "undionly.kpxe",
      "next-server": "10.0.132.217",
#      "tftp-server-name":
      "option-data": [ {
          "name": "tftp-server-name",
          "code": 66, "space": "dhcp4", "csv-format": true,
          "data": "10.0.132.217"
        } ] } ],
  "subnet4": [ {
      "subnet": "10.0.0.0/16",
      "client-class": "pxeclient",
      "match-client-id": false,
      "relay": { "ip-address": "10.0.0.17" },
      "pools": [ { "pool": "10.0.6.255-10.0.7.3" } ]
  ] }, ...

the upstream DHCP server defines a pool of 10.0.7.0 to 10.0.8.250, and
so I would expect the PXE client to obtain an address in that range. I
put mine one-different to test, and when I boot a PXE client, it
obtains 10.0.6.255. this is the case for _any_ pool that I define - it
gets the first address available in the pool.

Looking at the logs, I don't see any mention of any attempt to relay:
=============
0.976 DEBUG [kea-dhcp4.options/8] DHCP4_BUFFER_UNPACK parsing buffer
received from 0.0.0.0 to 255.255.255.255 over interface enp0s3
0.976 DEBUG [kea-dhcp4.eval/8] EVAL_DEBUG_OPTION Pushing option 60
with value 'PXEClient:Arch:00000:UNDI:002001'
0.976 DEBUG [kea-dhcp4.eval/8] EVAL_DEBUG_SUBSTRING Popping length 9,
start 0, string 0x... pushing result 0x505845436C69656E74
0.976 DEBUG [kea-dhcp4.eval/8] EVAL_DEBUG_EQUAL Popping
0x505845436C69656E74 and 0x505845436C69656E74 pushing result 'true'
0.976 INFO  [kea-dhcp4.options/8] EVAL_RESULT Expression pxeclient
evaluated to 1
0.976 DEBUG [kea-dhcp4.dhcpsrv/8] DHCPSRV_CFGMGR_SUBNET4_ADDR selected
subnet 10.0.0.0/16 for packet received by matching address
10.0.132.217
0.976 DEBUG [kea-dhcp4.packets/8] DHCP4_SUBNET_SELECTED [hwtype=1
08:00:27:16:f9:b3], cid=[no info], tid=0x2816f9b3: the subnet with ID
1 was selected for client assignments
0.976 DEBUG [kea-dhcp4.packets/8] DHCP4_SUBNET_DATA [hwtype=1
08:00:27:16:f9:b3], cid=[no info], tid=0x2816f9b3: the selected subnet
details: 10.0.0.0/16
0.976 DEBUG [kea-dhcp4.packets/8] DHCP4_PACKET_RECEIVED [hwtype=1
08:00:27:16:f9:b3], cid=[no info], tid=0x2816f9b3: DHCPDISCOVER (type
1) received from 0.0.0.0 to 255.255.255.255 on interface enp0s3
0.976 DEBUG [kea-dhcp4.packets/8] DHCP4_QUERY_DATA [hwtype=1
08:00:27:16:f9:b3], cid=[no info], tid=0x2816f9b3, packet details:
local_address=255.255.255.255:67, remote_adress=0.0.0.0:68,
msg_type=DHCPDISCOVER (1), transid=0x2816f9b3,
options:
  type=053, len=001: 1 (uint8)
  type=055, len=036: 1(uint8) 2(uint8) 3(uint8) 4(uint8) 5(uint8)
6(uint8) 11(uint8) 12(uint8) 13(uint8) 15(uint8) 16(uint8) 17(uint8)
18(uint8) 22(uint8) 23(uint8) 28(uint8) 40(uint8) 41(uint8) 42(uint8)
43(uint8) 50(uint8) 51(uint8) 54(uint8) 58(uint8) 59(uint8) 60(uint8)
66(uint8) 67(uint8) 128(uint8) 129(uint8) 130(uint8) 131(uint8)
132(uint8) 133(uint8) 134(uint8) 135(uint8)
  type=057, len=002: 1260 (uint16)
  type=060, len=032: "PXEClient:Arch:00000:UNDI:002001" (string)
  type=093, len=002: 0(uint16)
  type=094, len=003: 1 (uint8) 2 (uint8) 1 (uint8)
  type=097, len=017: 0 (uint8) FCD26F007982492F9A9FA7CA84B2E9AD (binary)
0.976 DEBUG [kea-dhcp4.dhcpsrv/8] DHCPSRV_CFGMGR_SUBNET4_ADDR selected
subnet 10.0.0.0/16 for packet received by matching address
10.0.132.217
0.976 DEBUG [kea-dhcp4.packets/8] DHCP4_SUBNET_SELECTED [hwtype=1
08:00:27:16:f9:b3], cid=[no info], tid=0x2816f9b3: the subnet with ID
1 was selected for client assignments
0.976 DEBUG [kea-dhcp4.packets/8] DHCP4_SUBNET_DATA [hwtype=1
08:00:27:16:f9:b3], cid=[no info], tid=0x2816f9b3: the selected subnet
details: 10.0.0.0/16
0.976 DEBUG [kea-dhcp4.dhcp4/8] DHCP4_CLIENTID_IGNORED_FOR_LEASES
[hwtype=1 08:00:27:16:f9:b3], cid=[no info], tid=0x2816f9b3: not using
client identifier for lease allocation for subnet 1
0.976 DEBUG [kea-dhcp4.hosts/8] HOSTS_CFG_GET_ONE_SUBNET_ID_IDENTIFIER
get one host with IPv4 reservation for subnet id 1, identified by
hwaddr=08002716F9B3
0.976 DEBUG [kea-dhcp4.hosts/8] HOSTS_CFG_GET_ALL_IDENTIFIER get all
hosts with reservations using identifier: hwaddr=08002716F9B3
0.976 DEBUG [kea-dhcp4.hosts/8] HOSTS_CFG_GET_ALL_IDENTIFIER_COUNT
using identifier hwaddr=08002716F9B3, found 0 host(s)
0.976 DEBUG [kea-dhcp4.hosts/8]
HOSTS_CFG_GET_ONE_SUBNET_ID_IDENTIFIER_NULL host not found using
subnet id 1 and identifier hwaddr=08002716F9B3
0.976 DEBUG [kea-dhcp4.dhcp4/8] DHCP4_CLASS_ASSIGNED [hwtype=1
08:00:27:16:f9:b3], cid=[no info], tid=0x2816f9b3: client packet has
been assigned to the following class(es):
VENDOR_CLASS_PXEClient:Arch:00000:UNDI:002001, pxeclient
0.977 DEBUG [kea-dhcp4.ddns/8] DHCP4_CLIENT_HOSTNAME_PROCESS [hwtype=1
08:00:27:16:f9:b3], cid=[no info], tid=0x2816f9b3: processing client's
Hostname option
0.977 DEBUG [kea-dhcp4.dhcpsrv/8] DHCPSRV_MEMFILE_GET_SUBID_HWADDR
obtaining IPv4 lease for subnet ID 1 and hardware address hwtype=1
08:00:27:16:f9:b3
0.977 DEBUG [kea-dhcp4.alloc-engine/8] ALLOC_ENGINE_V4_OFFER_NEW_LEASE
allocation engine will try to offer new lease to the client [hwtype=1
08:00:27:16:f9:b3], cid=[no info], tid=0x2816f9b3
0.977 DEBUG [kea-dhcp4.hosts/8] HOSTS_CFG_GET_ONE_SUBNET_ID_ADDRESS4
get one host with reservation for subnet id 1 and IPv4 address
10.0.6.255
0.977 DEBUG [kea-dhcp4.hosts/8] HOSTS_CFG_GET_ALL_ADDRESS4 get all
hosts with reservations for IPv4 address 10.0.6.255
0.977 DEBUG [kea-dhcp4.hosts/8] HOSTS_CFG_GET_ALL_ADDRESS4_COUNT using
address 10.0.6.255, found 0 host(s)
0.977 DEBUG [kea-dhcp4.hosts/8]
HOSTS_CFG_GET_ONE_SUBNET_ID_ADDRESS4_NULL host not found using subnet
id 1 and address 10.0.6.255
0.977 DEBUG [kea-dhcp4.dhcpsrv/8] DHCPSRV_MEMFILE_GET_ADDR4 obtaining
IPv4 lease for address 10.0.6.255
0.977 DEBUG [kea-dhcp4.dhcpsrv/8] DHCPSRV_MEMFILE_GET_ADDR4 obtaining
IPv4 lease for address 10.0.6.255
0.977 INFO  [kea-dhcp4.leases/8] DHCP4_LEASE_ADVERT [hwtype=1
08:00:27:16:f9:b3], cid=[no info], tid=0x2816f9b3: lease 10.0.6.255
will be advertised
0.977 DEBUG [kea-dhcp4.options/8] DHCP4_PACKET_PACK [hwtype=1
08:00:27:16:f9:b3], cid=[no info], tid=0x2816f9b3: preparing on-wire
format of the packet to be sent
0.977 DEBUG [kea-dhcp4.packets/8] DHCP4_PACKET_SEND [hwtype=1
08:00:27:16:f9:b3], cid=[no info], tid=0x2816f9b3: trying to send
packet DHCPOFFER (type 2) from 10.0.132.217:67 to 255.255.255.255:68
on interface enp0s3
0.977 DEBUG [kea-dhcp4.packets/8] DHCP4_RESPONSE_DATA [hwtype=1
08:00:27:16:f9:b3], cid=[no info], tid=0x2816f9b3: responding with
packet DHCPOFFER (type 2), packet details:
local_address=10.0.132.217:67, remote_adress=255.255.255.255:68,
msg_type=DHCPOFFER (2), transid=0x2816f9b3,
options:
  type=001, len=004: 4294901760 (uint32)
  type=051, len=004: 10 (uint32)
  type=053, len=001: 2 (uint8)
  type=054, len=004: 10.0.132.217
  type=066, len=012: "10.0.132.217" (string)
0.977 DEBUG [kea-dhcp4.packets/8] DHCP4_BUFFER_WAIT waiting for next
DHCPv4 packet with timeout 1000 ms
=============

To that end if I remove the pool (pools: [ ]), then the subnet is
selected, but not address is available:
0.651 DEBUG [kea-dhcp4.hosts/1004]
HOSTS_CFG_GET_ONE_SUBNET_ID_IDENTIFIER_NULL host not found using
subnet id 1 and identifier hwaddr=08002716F9B3
0.651 DEBUG [kea-dhcp4.dhcp4/1004] DHCP4_CLASS_ASSIGNED [hwtype=1
08:00:27:16:f9:b3], cid=[no info], tid=0x2b16f9b3: client packet has
been assigned to the following class(es):
VENDOR_CLASS_PXEClient:Arch:00000:UNDI:002001, pxeclient
0.651 DEBUG [kea-dhcp4.dhcpsrv/1004] DHCPSRV_MEMFILE_GET_SUBID_HWADDR
obtaining IPv4 lease for subnet ID 1 and hardware address hwtype=1
08:00:27:16:f9:b3
0.651 DEBUG [kea-dhcp4.alloc-engine/1004]
ALLOC_ENGINE_V4_OFFER_NEW_LEASE allocation engine will try to offer
new lease to the client [hwtype=1 08:00:27:16:f9:b3], cid=[no info],
tid=0x2b16f9b3
0.651 WARN  [kea-dhcp4.alloc-engine/1004] ALLOC_ENGINE_V4_ALLOC_FAIL
[hwtype=1 08:00:27:16:f9:b3], cid=[no info], tid=0x2b16f9b3: failed to
allocate an IPv4 address after 0 attempt(s)
0.651 DEBUG [kea-dhcp4.bad-packets/1004] DHCP4_PACKET_NAK_0003
[hwtype=1 08:00:27:16:f9:b3], cid=[no info], tid=0x2b16f9b3: failed to
advertise a lease, client sent ciaddr 0.0.0.0, requested-ip-address
(no address)
=====

Adding the interface to the subnet doesn't change the behavior at all.
It seems to simply be that the relay isn't functioning. Does anyone
have an idea what's going wrong?