PfSense Wan DHCP issue (RFC 2131)
-
It seems PfSense isn't updated to the latest RFC, or atleast my isp (Telus) says so. So basicly this is what happens, I get my IP from my ISP and then for whatever reason, it drops it. My ISP says its PfSense as its sending the server request header of the IP address that it wants, instead of "zeros" they say. So I will just copy and paste the logs from my pfsense and the email that was sent to me with their logs as well… maybe someone can help shed some light on this issue.... thanks everyone!!!
PfSense Logs
Last 100 DHCP service log entries
Dec 17 21:38:13 dhclient[31811]: connection closed
Dec 17 21:38:13 dhclient[31811]: exiting.
Dec 17 21:38:20 dhclient: PREINIT
Dec 17 21:38:20 dhclient: Starting delete_old_states()
Dec 17 21:38:20 dhclient: Comparing IPs: Old: New:
Dec 17 21:38:20 dhclient[85138]: DHCPREQUEST on bge1 to 255.255.255.255 port 67
Dec 17 21:38:20 dhclient[85138]: DHCPACK from 173.182.207.20
Dec 17 21:38:20 dhclient: REBOOT
Dec 17 21:38:20 dhclient: Starting delete_old_states()
Dec 17 21:38:20 dhclient: Comparing IPs: Old: New: 75.157.237.26
Dec 17 21:38:20 dhclient: Starting add_new_address()
Dec 17 21:38:20 dhclient: ifconfig bge1 inet 75.157.237.26 netmask 255.255.255.0 broadcast 75.157.237.255
Dec 17 21:38:20 dhclient: New IP Address (bge1): 75.157.237.26
Dec 17 21:38:20 dhclient: New Subnet Mask (bge1): 255.255.255.0
Dec 17 21:38:20 dhclient: New Broadcast Address (bge1): 75.157.237.255
Dec 17 21:38:20 dhclient: New Routers (bge1): 75.157.237.1
Dec 17 21:38:20 dhclient: Adding new routes to interface: bge1
Dec 17 21:38:20 dhclient: /sbin/route add default 75.157.237.1
Dec 17 21:38:20 dhclient: Creating resolv.conf
Dec 17 21:38:20 dhclient[85138]: bound to 75.157.237.26 – renewal in 43200 seconds.
Dec 18 09:38:20 dhclient[92031]: DHCPREQUEST on bge1 to 173.182.207.20 port 67
Dec 18 09:38:20 dhclient[92031]: DHCPACK from 173.182.207.20
Dec 18 09:38:20 dhclient: RENEW
Dec 18 09:38:20 dhclient: Creating resolv.conf
Dec 18 09:38:20 dhclient[92031]: bound to 75.157.237.26 – renewal in 43200 seconds.Email from my ISP
Good afternoon Matt,As discussed over the phone today, the TELUS Network Policy Management and Network Support agents who’ve been investigating your ongoing issue with your Static IP address 75.157.237.26 and came to the following conclusion:
The device is invalidating the DHCP cache causing a release of the IP. Then the device is requesting an IP for DHCP lease renewal on an already released IP as per RFC 2131. (see below)
This specific result is caused by a miss-configured device.
DHCP Cache invalidation is most likely caused by DHCP lease renewal done before lease is eligible to lease renewal.(Here is an example of logs demonstrating the result of the conclusion) –
Nov 26 23:33:07 bcvsscdhcp01 dhcpd[17179]: [ID 494714 local7.notice] [tid:62] NTCE DHCPOP(103) Protocol: DHCPRequest for 75.157.237.26 from 00:21:9b:fc:d4:fe (chAddr=00:21:9b:fc:d4:fe) via 75.157.237.1.
Nov 26 23:33:07 bcvsscdhcp01 dhcpd[17179]: [ID 699553 local7.info] [tid:62] INFO DHCP(405) Requested address 75.157.237.26 was not found to be associated with the client 00:21:9b:fc:d4:fe.
Nov 26 23:33:07 bcvsscdhcp01 dhcpd[17179]: [ID 946753 local7.warning] [tid:62] WARN DHCPOP(105) Protocol: DHCPNak on 75.157.237.26 to 00:21:9b:fc:d4:fe (chAddr=00:21:9b:fc:d4:fe) via 75.157.237.1. Server can't acknowledge requested address.
Nov 26 23:33:21 bcvsscdhcp01 dhcpd[17179]: [ID 988538 local7.notice] [tid:45] NTCE DHCPOP(101) Protocol: DHCPDiscover from 00:21:9b:fc:d4:fe (chAddr=00:21:9b:fc:d4:fe) via 75.157.237.1.
Nov 26 23:33:21 bcvsscdhcp01 dhcpd[17179]: [ID 241040 local7.notice] [tid:45] NTCE DHCPOP(102) Protocol: DHCPOffer on 75.157.237.26 to 00:21:9b:fc:d4:fe (chAddr=00:21:9b:fc:d4:fe) via 75.157.237.1.
Nov 26 23:33:23 bcvsscdhcp01 dhcpd[17179]: [ID 494714 local7.notice] [tid:75] NTCE DHCPOP(103) Protocol: DHCPRequest for 75.157.237.26 from 00:21:9b:fc:d4:fe (chAddr=00:21:9b:fc:d4:fe) via 75.157.237.1.
Nov 26 23:33:23 bcvsscdhcp01 dhcpd[17179]: [ID 555038 local7.notice] [tid:75] NTCE DHCPOP(104) Protocol: DHCPAck on 75.157.237.26 to 00:21:9b:fc:d4:fe (chAddr=00:21:9b:fc:d4:fe) via 75.157.237.1.
Nov 27 11:53:58 bcvsscdhcp01 dhcpd[17179]: [ID 494714 local7.notice] [tid:48] NTCE DHCPOP(103) Protocol: DHCPRequest for 75.157.237.26 from 00:21:9b:fc:d4:fe (chAddr=00:21:9b:fc:d4:fe) via e1000g0.
Nov 27 11:53:58 bcvsscdhcp01 dhcpd[17179]: [ID 555038 local7.notice] [tid:48] NTCE DHCPOP(104) Protocol: DHCPAck on 75.157.237.26 to 00:21:9b:fc:d4:fe (chAddr=00:21:9b:fc:d4:fe) via e1000g0.
Nov 27 12:08:14 bcvsscdhcp01 dhcpd[17179]: [ID 778926 local7.notice] [tid:51] NTCE DHCPOP(110) Protocol: DHCPCacheInvalidation message received for IP 75.157.237.26.
Nov 27 12:08:14 bcvsscdhcp01 dhcpd[17179]: [ID 820347 local7.notice] [tid:32] NTCE DHCPOP(106) Protocol: DHCPRelease of 75.157.237.26 from 00:21:9b:fc:d4:fe (chAddr=00:21:9b:fc:d4:fe) via e1000g0.
Nov 27 12:11:24 bcvsscdhcp01 dhcpd[17179]: [ID 494714 local7.notice] [tid:77] NTCE DHCPOP(103) Protocol: DHCPRequest for 75.157.237.26 from 00:21:9b:fc:d4:fe (chAddr=00:21:9b:fc:d4:fe) via 75.157.237.1.
Nov 27 12:11:24 bcvsscdhcp01 dhcpd[17179]: [ID 699553 local7.info] [tid:77] INFO DHCP(405) Requested address 75.157.237.26 was not found to be associated with the client 00:21:9b:fc:d4:fe.
Nov 27 12:11:24 bcvsscdhcp01 dhcpd[17179]: [ID 946753 local7.warning] [tid:77] WARN DHCPOP(105) Protocol: DHCPNak on 75.157.237.26 to 00:21:9b:fc:d4:fe (chAddr=00:21:9b:fc:d4:fe) via 75.157.237.1. Server can't acknowledge requested address.
Nov 27 12:11:39 bcvsscdhcp01 dhcpd[17179]: [ID 988538 local7.notice] [tid:40] NTCE DHCPOP(101) Protocol: DHCPDiscover from 00:21:9b:fc:d4:fe (chAddr=00:21:9b:fc:d4:fe) via 75.157.237.1.
Nov 27 12:11:39 bcvsscdhcp01 dhcpd[17179]: [ID 241040 local7.notice] [tid:40] NTCE DHCPOP(102) Protocol: DHCPOffer on 75.157.237.26 to 00:21:9b:fc:d4:fe (chAddr=00:21:9b:fc:d4:fe) via 75.157.237.1.
Nov 27 12:11:41 bcvsscdhcp01 dhcpd[17179]: [ID 494714 local7.notice] [tid:32] NTCE DHCPOP(103) Protocol: DHCPRequest for 75.157.237.26 from 00:21:9b:fc:d4:fe (chAddr=00:21:9b:fc:d4:fe) via 75.157.237.1.
Nov 27 12:11:41 bcvsscdhcp01 dhcpd[17179]: [ID 555038 local7.notice] [tid:32] NTCE DHCPOP(104) Protocol: DHCPAck on 75.157.237.26 to 00:21:9b:fc:d4:fe (chAddr=00:21:9b:fc:d4:fe) via 75.157.237.1.
Nov 27 14:12:51 bcvsscdhcp01 dhcpd[17179]: [ID 778926 local7.notice] [tid:84] NTCE DHCPOP(110) Protocol: DHCPCacheInvalidation message received for IP 75.157.237.26.
Nov 27 14:12:52 bcvsscdhcp01 dhcpd[17179]: [ID 820347 local7.notice] [tid:81] NTCE DHCPOP(106) Protocol: DHCPRelease of 75.157.237.26 from 00:21:9b:fc:d4:fe (chAddr=00:21:9b:fc:d4:fe) via e1000g0.RFC 2131 Dynamic Host Configuration Protocol March 1997
be ignored by servers, and multiple servers may, therefore, not
return identical values for some options. The 'requested IP address'
option is to be filled in only in a DHCPREQUEST message when the
client is verifying network parameters obtained previously. The
client fills in the 'ciaddr' field only when correctly configured
with an IP address in BOUND, RENEWING or REBINDING state.If a server receives a DHCPREQUEST message with an invalid 'requested
IP address', the server SHOULD respond to the client with a DHCPNAK
message and may choose to report the problem to the system
administrator. The server may include an error message in the
'message' option.RFC 1531 Dynamic Host Configuration Protocol October 1993
In the second case, when there is no 'server identifier' option, the
client is renewing or extending a previously allocated IP address.
The server checks to confirm that the requested parameters are
acceptable. If the parameters specified in the DHCPREQUEST message
match the previous parameters, or if the request for an extension of
the lease (indicated by an extended 'IP address lease time' option)
is acceptable, the server returns a DHCPACK message to the requesting
client. Otherwise, the server returns a DHCPNAK message to the client.
In particular, if the previously allocated network address
in the 'ciaddr' field from the client does not match the network
address recorded by the server for that client, the server sends a
DHCPNAK to the client.A DHCP server chooses the parameters to return in a DHCPACK message
according to the same rules as used in constructing a DHCPOFFER
message, as given in section 4.3.1.I hope that this e-mail clarifies this ongoing situation.
Regards,
Karl Drake Woloshyn
TELUS Customer Solutions, Small Medium Business -
No one? Should this be reported as a bug or what?
-
I know that this is an old topic, but I recently just ran into this problem after setting up pfsense and a bridged Actiontec T2200 and did resolve it, so I figured I would post here in case someone stumbles across this thread like I did. After running a network capture between the Actiontec modem and my pfsense system, I found that pfsense was holding onto the last IP address that it had received while NATed behind the Actiontec in non-bridged mode. So what was happening was pfsense was sending a DHCP REQUEST packet with the private IP address and Telus DHCP was coming back with a DHCP NAK because private addresses are not allowed at customer endpoints. Makes sense. Pfsense was not giving this private address lease up though, so I had to wait until the lease had timed out on pfsense before forcing an IP renewal. At that point, it made a DHCP request with 0.0.0.0, which Telus's DHCP servers then responded to with a public IP.
I think this may highlight a bug in pfsense 2.3 though, that Status -> Interfaces -> WAN release button does not appear to properly release the IP address.