[Kea-users] kea-dhcp4 version1.8 , unable to send response packet

Fri Mar 26 16:52:16 UTC 2021

>This Setup was working fne under version 1.6 but with 1.8 the server isn't able to send packets back to client.
>
>The log shows that everything is working fine until a response should be sent to client
>": failed to send DHCPv4 packet: Interface tun1/8 does not have any suitable IPv4 sockets open."

Replay to my own message

I have done some strace and it seems the tunnel interface is the problem.

In DHCP4_PACKET_SEND everything looks ok - 172.16.160.248 is the loopback IP on which the request was received and 192.168.168.200.254
is the Interface on the router with the Cisco IP Helper.

DHCP4_RESPONSE_DATA shows the right DHCPOFFER

Then the DHCP4_PACKET_SEND_FAIL Message - tun1 is the interface on which the packet was received.
I think the right way should be sending the packet through the loopback and the linux stack should do the rest.

16:46:02 write(5, "2021-03-26 16:46:02.116 DEBUG [kea-dhcp4.options/13945.140485403977856] DHCP4_PACKET_PACK [hwtype=1 f4:cf:e2:98:75:e1], cid=[00:63:69:73:63:6f:2d:66:34:63:66:2e:65:32:39:38:2e:37:35:65:31:2d:47:69:30:2f:31:2e:39:30:30], tid=0x14ea: preparing on-wire format of the packet to be sent\n", 282) = 282 <0.000011>
16:46:02 lseek(5, 0, SEEK_CUR)          = 9600239 <0.000009>
16:46:02 fcntl(4, F_SETLKW, {l_type=F_UNLCK, l_whence=SEEK_SET, l_start=0, l_len=0}) = 0 <0.000010>
16:46:02 fcntl(26, F_SETLKW, {l_type=F_UNLCK, l_whence=SEEK_SET, l_start=0, l_len=1}) = 0 <0.000010>
16:46:02 fcntl(25, F_SETLKW, {l_type=F_WRLCK, l_whence=SEEK_SET, l_start=0, l_len=1}) = 0 <0.000011>
16:46:02 fcntl(4, F_SETLKW, {l_type=F_WRLCK, l_whence=SEEK_SET, l_start=0, l_len=0}) = 0 <0.000010>
16:46:02 lseek(5, 0, SEEK_END)          = 9600239 <0.000010>
16:46:02 lseek(5, 0, SEEK_CUR)          = 9600239 <0.000009>
16:46:02 lseek(5, 0, SEEK_END)          = 9600239 <0.000010>
16:46:02 write(5, "2021-03-26 16:46:02.117 DEBUG [kea-dhcp4.packets/13945.140485403977856] DHCP4_PACKET_SEND [hwtype=1 f4:cf:e2:98:75:e1], cid=[00:63:69:73:63:6f:2d:66:34:63:66:2e:65:32:39:38:2e:37:35:65:31:2d:47:69:30:2f:31:2e:39:30:30], tid=0x14ea: trying to send packet DHCPOFFER (type 2) from 172.16.160.248:67 to 192.168.200.254:67 on interface lo\n", 334) = 334 <0.000016>
16:46:02 lseek(5, 0, SEEK_CUR)          = 9600573 <0.000010>
16:46:02 fcntl(4, F_SETLKW, {l_type=F_UNLCK, l_whence=SEEK_SET, l_start=0, l_len=0}) = 0 <0.000010>
16:46:02 fcntl(25, F_SETLKW, {l_type=F_UNLCK, l_whence=SEEK_SET, l_start=0, l_len=1}) = 0 <0.000010>
16:46:02 fcntl(25, F_SETLKW, {l_type=F_WRLCK, l_whence=SEEK_SET, l_start=0, l_len=1}) = 0 <0.000011>
16:46:02 fcntl(4, F_SETLKW, {l_type=F_WRLCK, l_whence=SEEK_SET, l_start=0, l_len=0}) = 0 <0.000010>
16:46:02 lseek(5, 0, SEEK_END)          = 9600573 <0.000010>
16:46:02 lseek(5, 0, SEEK_CUR)          = 9600573 <0.000010>
16:46:02 lseek(5, 0, SEEK_END)          = 9600573 <0.000010>
16:46:02 write(5, "2021-03-26 16:46:02.117 DEBUG [kea-dhcp4.packets/13945.140485403977856] DHCP4_RESPONSE_DATA [hwtype=1 f4:cf:e2:98:75:e1], cid=[00:63:69:73:63:6f:2d:66:34:63:66:2e:65:32:39:38:2e:37:35:65:31:2d:47:69:30:2f:31:2e:39:30:30], tid=0x14ea: responding with packet DHCPOFFER (type 2), packet details: local_address=172.16.160.248:67, remote_address=192.168.200.254:67, msg_type=DHCPOFFER (2), transid=0x14ea,\noptions:\n  type=001, len=004: 4294967040 (uint32)\n  type=003, len=004: 192.168.200.254\n  type=006, len=008: 8.8.8.8 9.9.9.9\n  type=012, len=014: \"config-station\" (string)\n  type=051, len=004: 28800 (uint32)\n  type=053, len=001: 2 (uint8)\n  type=054, len=004: 172.16.160.248\n  type=061, len=031: 00:63:69:73:63:6f:2d:66:34:63:66:2e:65:32:39:38:2e:37:35:65:31:2d:47:69:30:2f:31:2e:39:30:30\n", 802) = 802 <0.000018>
16:46:02 lseek(5, 0, SEEK_CUR)          = 9601375 <0.000010>
16:46:02 fcntl(4, F_SETLKW, {l_type=F_UNLCK, l_whence=SEEK_SET, l_start=0, l_len=0}) = 0 <0.000010>
16:46:02 fcntl(25, F_SETLKW, {l_type=F_UNLCK, l_whence=SEEK_SET, l_start=0, l_len=1}) = 0 <0.000010>
16:46:02 fcntl(25, F_SETLKW, {l_type=F_WRLCK, l_whence=SEEK_SET, l_start=0, l_len=1}) = 0 <0.000010>
16:46:02 fcntl(4, F_SETLKW, {l_type=F_WRLCK, l_whence=SEEK_SET, l_start=0, l_len=0}) = 0 <0.000009>
16:46:02 lseek(5, 0, SEEK_END)          = 9601375 <0.000008>
16:46:02 lseek(5, 0, SEEK_CUR)          = 9601375 <0.000009>
16:46:02 lseek(5, 0, SEEK_END)          = 9601375 <0.000009>
16:46:02 write(5, "2021-03-26 16:46:02.118 ERROR [kea-dhcp4.packets/13945.140485403977856] DHCP4_PACKET_SEND_FAIL [hwtype=1 f4:cf:e2:98:75:e1], cid=[00:63:69:73:63:6f:2d:66:34:63:66:2e:65:32:39:38:2e:37:35:65:31:2d:47:69:30:2f:31:2e:39:30:30], tid=0x14ea: failed to send DHCPv4 packet: Interface tun1/8 does not have any suitable IPv4 sockets open.\n", 330) = 330 <0.000016>
16:46:02 lseek(5, 0, SEEK_CUR)          = 9601705 <0.000009>
16:46:02 fcntl(4, F_SETLKW, {l_type=F_UNLCK, l_whence=SEEK_SET, l_start=0, l_len=0}) = 0 <0.000009>
16:46:02 fcntl(25, F_SETLKW, {l_type=F_UNLCK, l_whence=SEEK_SET, l_start=0, l_len=1}) = 0 <0.000008>

If we change the interface config to 
"outbound-interface": "use-routing"
 it's working !

    "interfaces-config": {
        "interfaces": [ "lo/172.16.160.248" ],
        "dhcp-socket-type": "udp",
          "outbound-interface": "use-routing"
        // "outbound-interface": "same-as-inbound"
       // same as inbound is default
    },

This is a work around but it's not so easy for debugging - tracing packets over different interfaces needs much more effort.
We also have to modify the firewalls rules to leave this traffic out which wasn't seen by firewall (was arrived through the gre tunnel)

I have also tried to bind kea-dchp4 directly to the gre tunnel which failed too.
It seems that kea-dhcp4 select the wrong IP address for binding .
It is using the Tunnel PEER_INNER address.
Maybe this is also the reason for the message above (tun1/8 does not have any suitable IPv4 sockets open)

#GRE Tunnel Config
#cat ifcfg-tun1
DEVICE=tun1
BOOTPROTO=none
ONBOOT=yes
TYPE=GRE
PEER_OUTER_IPADDR=172.16.213.253
PEER_INNER_IPADDR=172.16.200.254/24
MY_OUTER_IPADDR=10.214.200.4
MY_INNER_IPADDR=172.16.200.4/24

17:23:15 socket(AF_INET, SOCK_DGRAM, IPPROTO_IP) = 24 <0.000015>
17:23:15 fcntl(24, F_SETFD, FD_CLOEXEC) = 0 <0.000008>
17:23:15 bind(24, {sa_family=AF_INET, sin_port=htons(67), sin_addr=inet_addr("172.16.160.248")}, 16) = 0 <0.000013>
17:23:15 setsockopt(24, SOL_IP, IP_PKTINFO, [1], 4) = 0 <0.000009>
17:23:15 socket(AF_INET, SOCK_DGRAM, IPPROTO_IP) = 25 <0.000011>
17:23:15 fcntl(25, F_SETFD, FD_CLOEXEC) = 0 <0.000008>
17:23:15 bind(25, {sa_family=AF_INET, sin_port=htons(67), sin_addr=inet_addr("172.16.200.254")}, 16) = -1 EADDRNOTAVAIL (Die angeforderte Adresse kann nicht zugewiesen werden) <0.000009>
17:23:15 close(25)                      = 0 <0.000015>
17:23:15 fcntl(8, F_SETLKW, {l_type=F_WRLCK, l_whence=SEEK_SET, l_start=0, l_len=1}) = 0 <0.000012>
17:23:15 fcntl(4, F_SETLKW, {l_type=F_WRLCK, l_whence=SEEK_SET, l_start=0, l_len=0}) = 0 <0.000010>
17:23:15 lseek(5, 0, SEEK_END)          = 9296497 <0.000008>
17:23:15 lseek(5, 0, SEEK_CUR)          = 9296497 <0.000008>
17:23:15 lseek(5, 0, SEEK_END)          = 9296497 <0.000008>
17:23:15 write(5, "2021-03-25 17:23:15.918 WARN  [kea-dhcp4.dhcpsrv/18423.139928109389952] DHCPSRV_OPEN_SOCKET_FAIL failed to open socket: failed to open socket on interface tun1, reason: Failed to bind socket 25 to 172.16.200.254/port=67\n", 220) = 220 <0.000015>
17:23:15 lseek(5, 0, SEEK_CUR)          = 9296717 <0.000008>
17:23:15 fcntl(4, F_SETLKW, {l_type=F_UNLCK, l_whence=SEEK_SET, l_start=0, l_len=0}) = 0 <0.000009>
17:23:15 fcntl(8, F_SETLKW, {l_type=F_UNLCK, l_whence=SEEK_SET, l_start=0, l_len=1}) = 0 <0.000009>
17:23:15 fcntl(8, F_SETLKW, {l_type=F_WRLCK, l_whence=SEEK_SET, l_start=0, l_len=1}) = 0 <0.000010>
17:23:15 fcntl(4, F_SETLKW, {l_type=F_WRLCK, l_whence=SEEK_SET, l_start=0, l_len=0}) = 0 <0.000009>