New ISP - arpresolve: can't allocate llinfo for X.X.X.X on mvneta0.4090
-
Are you running 2.4.5p1?
It sounds close to this but that was resolved in 2.4.5:
https://redmine.pfsense.org/issues/9267Check the dhcp logs though is the dhclient continually trying to pull a new lease or just stops?
Steve
-
First thanks for responding to my post.
I am running latest version 2.4.5-RELEASE-p1 (arm64)
Have DHCP logs set to latest 100 entries. Had to release the WAN then renew WAN at Status -> Interfaces just prior to reading this post and writing this response. Beginning of logs are filled with DHCP entries from LAN and local machines. At the bottom I copy and paste the following:
Nov 15 09:05:31 dhclient 97961 connection closed
Nov 15 09:05:31 dhclient 97961 exiting.
Nov 15 09:05:38 dhclient PREINIT
Nov 15 09:05:38 dhclient 66357 DHCPREQUEST on mvneta0.4090 to 255.255.255.255 port 67
Nov 15 09:05:38 dhclient 66357 DHCPACK from 146.86.160.3
Nov 15 09:05:38 dhclient REBOOT
Nov 15 09:05:39 dhclient Starting add_new_address()
Nov 15 09:05:39 dhclient ifconfig mvneta0.4090 inet 146.86.167.83 netmask 255.255.248.0 broadcast 146.86.167.255
Nov 15 09:05:39 dhclient New IP Address (mvneta0.4090): 146.86.167.83
Nov 15 09:05:39 dhclient New Subnet Mask (mvneta0.4090): 255.255.248.0
Nov 15 09:05:39 dhclient New Broadcast Address (mvneta0.4090): 146.86.167.255
Nov 15 09:05:39 dhclient New Routers (mvneta0.4090): 146.86.160.1
Nov 15 09:05:39 dhclient Adding new routes to interface: mvneta0.4090
Nov 15 09:05:39 dhclient /sbin/route add default 146.86.160.1
Nov 15 09:05:39 dhclient Creating resolv.conf
Nov 15 09:05:39 dhclient 66357 bound to 146.86.167.83 -- renewal in 302400 seconds.
Nov 15 09:05:45 dhcpd Internet Systems Consortium DHCP Server 4.4.1
Nov 15 09:05:45 dhcpd Copyright 2004-2018 Internet Systems Consortium.
Nov 15 09:05:45 dhcpd All rights reserved.
Nov 15 09:05:45 dhcpd For info, please visit https://www.isc.org/software/dhcp/
Nov 15 09:05:45 dhcpd Config file: /etc/dhcpd.conf
Nov 15 09:05:45 dhcpd Database file: /var/db/dhcpd.leases
Nov 15 09:05:45 dhcpd Internet Systems Consortium DHCP Server 4.4.1
Nov 15 09:05:45 dhcpd PID file: /var/run/dhcpd.pid
Nov 15 09:05:45 dhcpd Copyright 2004-2018 Internet Systems Consortium.
Nov 15 09:05:45 dhcpd All rights reserved.
Nov 15 09:05:45 dhcpd For info, please visit https://www.isc.org/software/dhcp/
Nov 15 09:05:45 dhcpd Wrote 0 deleted host decls to leases file.
Nov 15 09:05:45 dhcpd Wrote 0 new dynamic host decls to leases file.
Nov 15 09:05:45 dhcpd Wrote 20 leases to leases file.
Nov 15 09:05:45 dhcpd Listening on BPF/mvneta0.4091/f0:ad:4e:0b:9e:26/192.168.1.0/24
Nov 15 09:05:45 dhcpd Sending on BPF/mvneta0.4091/f0:ad:4e:0b:9e:26/192.168.1.0/24
Nov 15 09:05:45 dhcpd Sending on Socket/fallback/fallback-net
Nov 15 09:05:45 dhcpd Server starting service.Also from System -> General Log
Nov 15 09:05:38 kernel arpresolve: can't allocate llinfo for 146.86.160.1 on mvneta0.4090
Nov 15 09:05:39 check_reload_status rc.newwanip starting mvneta0.4090
Nov 15 09:05:40 php-fpm 64315 /rc.newwanip: rc.newwanip: Info: starting on mvneta0.4090.
Nov 15 09:05:40 php-fpm 64315 /rc.newwanip: rc.newwanip: on (IP address: 146.86.167.83) (interface: WAN[wan]) (real interface: mvneta0.4090).
Nov 15 09:05:42 php-fpm 64315 /rc.newwanip: Removing static route for monitor 142.202.164.42 and adding a new route through 146.86.160.1
Nov 15 09:05:43 php-fpm 64315 /rc.newwanip: Gateway, none 'available' for inet6, use the first one configured. ''
Nov 15 09:05:48 php-fpm 64315 /rc.newwanip: phpDynDNS (): No change in my IP address and/or 25 days has not passed. Not updating dynamic DNS entry.
Nov 15 09:05:49 php-fpm 64315 /rc.newwanip: Resyncing OpenVPN instances for interface WAN.
Nov 15 09:05:50 php-fpm 64315 OpenVPN terminate old pid: 79593
Nov 15 09:05:50 php-fpm 64315 OpenVPN PID written: 54011
Nov 15 09:05:50 check_reload_status Reloading filter
Nov 15 09:05:50 php-fpm 64315 /rc.newwanip: Creating rrd update script
Nov 15 09:05:52 php-fpm 64315 /rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - 146.86.167.83 -> 146.86.167.83 - Restarting packages.
Nov 15 09:05:52 check_reload_status Starting packages
Nov 15 09:05:54 php-fpm 18933 /rc.start_packages: Restarting/Starting all packages.And from System -> Gateway Log
Nov 15 09:04:37 dpinger WAN_DHCP 142.202.164.42: Alarm latency 6943us stddev 1065us loss 22%
Nov 15 09:05:43 dpinger send_interval 500ms loss_interval 2000ms time_period 60000ms report_interval 0ms data_len 1 alert_interval 1000ms latency_alarm 500ms loss_alarm 20% dest_addr 142.202.164.42 bind_addr 146.86.167.83 identifier "WAN_DHCP "And from System -> Routing Logs
Nov 15 09:05:34 radvd 29766 exiting, 1 sigterm(s) received
Nov 15 09:05:34 radvd 29766 sending stop adverts
Nov 15 09:05:34 radvd 29766 removing /var/run/radvd.pid
Nov 15 09:05:34 radvd 29766 returning from radvd main
Nov 15 09:05:46 radvd 4364 version 2.18 startedDoes that help you or explain anything?
Chuck
-
Ok so it went down at 9:04. What you want to check is the dhcp log covering that period.
You can increase the number of logs shown up to ~2000 but you probably don't need many. Just filter the log by the dhclient process:
Check to see if it was continually retrying while the WAN was down or just hit an error and stopped.
Steve
-
Steve, again thanks for your response and instructions!!
See below as I think this may be the pertinent part of the log. First I increased records to 500, then filtered the process as suggested on "dhclient'.
Nov 14 22:00:05 dhclient 2500 bound to 146.86.167.83 -- renewal in 302400 seconds.
Nov 14 22:43:18 dhclient 3162 connection closed
Nov 14 22:43:18 dhclient 3162 exiting.
Nov 14 22:43:29 dhclient PREINIT
Nov 14 22:43:29 dhclient 38678 DHCPREQUEST on mvneta0.4090 to 255.255.255.255 port 67
Nov 14 22:43:31 dhclient 38678 DHCPREQUEST on mvneta0.4090 to 255.255.255.255 port 67
Nov 14 22:43:35 dhclient 38678 DHCPREQUEST on mvneta0.4090 to 255.255.255.255 port 67
Nov 14 22:43:44 dhclient 38678 DHCPDISCOVER on mvneta0.4090 to 255.255.255.255 port 67 interval 2
Nov 14 22:43:46 dhclient 38678 DHCPDISCOVER on mvneta0.4090 to 255.255.255.255 port 67 interval 4
Nov 14 22:43:50 dhclient 38678 DHCPDISCOVER on mvneta0.4090 to 255.255.255.255 port 67 interval 4
Nov 14 22:43:54 dhclient 38678 DHCPDISCOVER on mvneta0.4090 to 255.255.255.255 port 67 interval 5
Nov 14 22:43:59 dhclient 38678 DHCPDISCOVER on mvneta0.4090 to 255.255.255.255 port 67 interval 5
Nov 14 22:44:04 dhclient 38678 DHCPDISCOVER on mvneta0.4090 to 255.255.255.255 port 67 interval 12
Nov 14 22:44:16 dhclient 38678 DHCPDISCOVER on mvneta0.4090 to 255.255.255.255 port 67 interval 8
Nov 14 22:44:24 dhclient 38678 DHCPDISCOVER on mvneta0.4090 to 255.255.255.255 port 67 interval 19
Nov 14 22:44:43 dhclient 38678 DHCPDISCOVER on mvneta0.4090 to 255.255.255.255 port 67 interval 2
Nov 14 22:44:45 dhclient 38678 No DHCPOFFERS received.
Nov 14 22:44:45 dhclient 38678 Trying recorded lease 146.86.167.83
Nov 14 22:44:45 dhclient TIMEOUT
Nov 14 22:44:45 dhclient Starting add_new_address()
Nov 14 22:44:45 dhclient ifconfig mvneta0.4090 inet 146.86.167.83 netmask 255.255.248.0 broadcast 146.86.167.255
Nov 14 22:44:45 dhclient New IP Address (mvneta0.4090): 146.86.167.83
Nov 14 22:44:45 dhclient New Subnet Mask (mvneta0.4090): 255.255.248.0
Nov 14 22:44:45 dhclient New Broadcast Address (mvneta0.4090): 146.86.167.255
Nov 14 22:44:45 dhclient New Routers (mvneta0.4090): 146.86.160.1
Nov 14 22:44:46 dhclient New Routers (mvneta0.4090): 146.86.160.1
Nov 14 22:44:47 dhclient Deleting old routes
Nov 14 22:44:47 dhclient 38678 No working leases in persistent database - sleeping.
Nov 14 22:44:47 dhclient FAIL
Nov 14 22:44:47 dhclient 39684 connection closed
Nov 14 22:44:47 dhclient 39684 exiting.
Nov 14 22:44:50 dhclient PREINIT
Nov 14 22:44:50 dhclient 21343 DHCPREQUEST on mvneta0.4090 to 255.255.255.255 port 67
Nov 14 22:44:52 dhclient 21343 DHCPREQUEST on mvneta0.4090 to 255.255.255.255 port 67
Nov 14 22:44:57 dhclient 21343 DHCPREQUEST on mvneta0.4090 to 255.255.255.255 port 67
Nov 14 22:45:09 dhclient 21343 DHCPDISCOVER on mvneta0.4090 to 255.255.255.255 port 67 interval 1
Nov 14 22:45:10 dhclient 21343 DHCPDISCOVER on mvneta0.4090 to 255.255.255.255 port 67 interval 2
Nov 14 22:45:10 dhclient 21343 DHCPOFFER from 146.86.160.3
Nov 14 22:45:10 dhclient ARPSEND
Nov 14 22:45:12 dhclient ARPCHECK
Nov 14 22:45:12 dhclient 21343 DHCPREQUEST on mvneta0.4090 to 255.255.255.255 port 67
Nov 14 22:45:12 dhclient 21343 DHCPACK from 146.86.160.3
Nov 14 22:45:12 dhclient BOUND
Nov 14 22:45:12 dhclient Starting add_new_address()
Nov 14 22:45:12 dhclient ifconfig mvneta0.4090 inet 146.86.167.83 netmask 255.255.248.0 broadcast 146.86.167.255
Nov 14 22:45:12 dhclient New IP Address (mvneta0.4090): 146.86.167.83
Nov 14 22:45:12 dhclient New Subnet Mask (mvneta0.4090): 255.255.248.0
Nov 14 22:45:12 dhclient New Broadcast Address (mvneta0.4090): 146.86.167.255
Nov 14 22:45:12 dhclient New Routers (mvneta0.4090): 146.86.160.1
Nov 14 22:45:12 dhclient Adding new routes to interface: mvneta0.4090
Nov 14 22:45:12 dhclient /sbin/route add default 146.86.160.1
Nov 14 22:45:12 dhclient Creating resolv.conf
Nov 14 22:45:12 dhclient 21343 bound to 146.86.167.83 -- renewal in 302400 seconds.
Nov 14 22:46:14 dhclient 23381 connection closed
Nov 14 22:46:14 dhclient 23381 exiting.
Nov 14 22:46:26 dhclient PREINIT
Nov 14 22:46:26 dhclient 56289 DHCPREQUEST on mvneta0.4090 to 255.255.255.255 port 67
Nov 14 22:46:27 dhclient 56289 DHCPREQUEST on mvneta0.4090 to 255.255.255.255 port 67
Nov 14 22:46:29 dhclient 56289 DHCPREQUEST on mvneta0.4090 to 255.255.255.255 port 67
Nov 14 22:46:33 dhclient 56289 DHCPREQUEST on mvneta0.4090 to 255.255.255.255 port 67
Nov 14 22:46:37 dhclient 56289 DHCPDISCOVER on mvneta0.4090 to 255.255.255.255 port 67 interval 2
Nov 14 22:46:39 dhclient 56289 DHCPDISCOVER on mvneta0.4090 to 255.255.255.255 port 67 interval 2
Nov 14 22:46:41 dhclient 56289 DHCPDISCOVER on mvneta0.4090 to 255.255.255.255 port 67 interval 3
Nov 14 22:46:44 dhclient 56289 DHCPDISCOVER on mvneta0.4090 to 255.255.255.255 port 67 interval 5
Nov 14 22:46:49 dhclient 56289 DHCPDISCOVER on mvneta0.4090 to 255.255.255.255 port 67 interval 6
Nov 14 22:46:55 dhclient 56289 DHCPDISCOVER on mvneta0.4090 to 255.255.255.255 port 67 interval 14
Nov 14 22:47:09 dhclient 56289 DHCPDISCOVER on mvneta0.4090 to 255.255.255.255 port 67 interval 14
Nov 14 22:47:23 dhclient 56289 DHCPDISCOVER on mvneta0.4090 to 255.255.255.255 port 67 interval 8
Nov 14 22:47:31 dhclient 56289 DHCPDISCOVER on mvneta0.4090 to 255.255.255.255 port 67 interval 7
Nov 14 22:47:38 dhclient 56289 No DHCPOFFERS received.
Nov 14 22:47:38 dhclient 56289 Trying recorded lease 146.86.167.83
Nov 14 22:47:38 dhclient TIMEOUT
Nov 14 22:47:38 dhclient Starting add_new_address()
Nov 14 22:47:38 dhclient ifconfig mvneta0.4090 inet 146.86.167.83 netmask 255.255.248.0 broadcast 146.86.167.255
Nov 14 22:47:38 dhclient New IP Address (mvneta0.4090): 146.86.167.83
Nov 14 22:47:38 dhclient New Subnet Mask (mvneta0.4090): 255.255.248.0
Nov 14 22:47:38 dhclient New Broadcast Address (mvneta0.4090): 146.86.167.255
Nov 14 22:47:38 dhclient New Routers (mvneta0.4090): 146.86.160.1
Nov 14 22:47:39 dhclient New Routers (mvneta0.4090): 146.86.160.1
Nov 14 22:47:40 dhclient Deleting old routes
Nov 14 22:47:40 dhclient 56289 No working leases in persistent database - sleeping.
Nov 14 22:47:40 dhclient FAIL
Nov 14 22:47:40 dhclient 56926 connection closed
Nov 14 22:47:40 dhclient 56926 exiting.
Nov 14 22:47:43 dhclient PREINIT
Nov 14 22:47:43 dhclient 69111 DHCPREQUEST on mvneta0.4090 to 255.255.255.255 port 67
Nov 14 22:47:44 dhclient 69111 DHCPREQUEST on mvneta0.4090 to 255.255.255.255 port 67
Nov 14 22:47:46 dhclient 69111 DHCPREQUEST on mvneta0.4090 to 255.255.255.255 port 67
Nov 14 22:47:50 dhclient 69111 DHCPREQUEST on mvneta0.4090 to 255.255.255.255 port 67
Nov 14 22:47:54 dhclient 69111 DHCPDISCOVER on mvneta0.4090 to 255.255.255.255 port 67 interval 2
Nov 14 22:47:56 dhclient 69111 DHCPDISCOVER on mvneta0.4090 to 255.255.255.255 port 67 interval 4
Nov 14 22:48:00 dhclient 69111 DHCPDISCOVER on mvneta0.4090 to 255.255.255.255 port 67 interval 11
Nov 14 22:48:11 dhclient 69111 DHCPDISCOVER on mvneta0.4090 to 255.255.255.255 port 67 interval 19
Nov 14 22:48:30 dhclient 69111 DHCPDISCOVER on mvneta0.4090 to 255.255.255.255 port 67 interval 7
Nov 14 22:48:30 dhclient 69111 DHCPOFFER from 146.86.160.3
Nov 14 22:48:30 dhclient ARPSEND
Nov 14 22:48:32 dhclient ARPCHECK
Nov 14 22:48:32 dhclient 69111 DHCPREQUEST on mvneta0.4090 to 255.255.255.255 port 67
Nov 14 22:48:32 dhclient 69111 DHCPACK from 146.86.160.3
Nov 14 22:48:32 dhclient BOUND
Nov 14 22:48:32 dhclient Starting add_new_address()
Nov 14 22:48:32 dhclient ifconfig mvneta0.4090 inet 146.86.167.83 netmask 255.255.248.0 broadcast 146.86.167.255
Nov 14 22:48:32 dhclient New IP Address (mvneta0.4090): 146.86.167.83
Nov 14 22:48:32 dhclient New Subnet Mask (mvneta0.4090): 255.255.248.0
Nov 14 22:48:32 dhclient New Broadcast Address (mvneta0.4090): 146.86.167.255
Nov 14 22:48:32 dhclient New Routers (mvneta0.4090): 146.86.160.1
Nov 14 22:48:32 dhclient Adding new routes to interface: mvneta0.4090
Nov 14 22:48:32 dhclient /sbin/route add default 146.86.160.1
Nov 14 22:48:32 dhclient Creating resolv.conf
Nov 14 22:48:32 dhclient 69111 bound to 146.86.167.83 -- renewal in 302400 seconds.
Nov 15 03:50:18 dhclient 70019 connection closedThe first entry in the list at 22:00 hours is the final entry of the last time I renewed the lease per my previous described process. The last entry in the list is the first entry of me (when I woke up) of again renewing the lease per my process. What is in between is me being asleep and not doing anything to the interface.
Note that as of about 11:00am local time today it went down, came back up on it's own then went down again then I renewed the lease at 12:55pm. The first entry is the last line of the renew prior to it going down and then my renewing of the lease again at 12:55 so I could respond to you.
Nov 15 09:51:31 dhclient 46098 bound to 146.86.167.83 -- renewal in 302400 seconds.
Nov 15 12:55:02 dhclient 46826 connection closed
Nov 15 12:55:02 dhclient 46826 exiting.
Nov 15 12:55:10 dhclient PREINIT
Nov 15 12:55:10 dhclient 24262 DHCPREQUEST on mvneta0.4090 to 255.255.255.255 port 67
Nov 15 12:55:10 dhclient 24262 DHCPACK from 146.86.160.3
Nov 15 12:55:10 dhclient REBOOT
Nov 15 12:55:10 dhclient Starting add_new_address()
Nov 15 12:55:10 dhclient ifconfig mvneta0.4090 inet 146.86.167.83 netmask 255.255.248.0 broadcast 146.86.167.255
Nov 15 12:55:11 dhclient New IP Address (mvneta0.4090): 146.86.167.83
Nov 15 12:55:11 dhclient New Subnet Mask (mvneta0.4090): 255.255.248.0
Nov 15 12:55:11 dhclient New Broadcast Address (mvneta0.4090): 146.86.167.255
Nov 15 12:55:11 dhclient New Routers (mvneta0.4090): 146.86.160.1
Nov 15 12:55:11 dhclient Adding new routes to interface: mvneta0.4090
Nov 15 12:55:11 dhclient /sbin/route add default 146.86.160.1
Nov 15 12:55:11 dhclient Creating resolv.conf
Nov 15 12:55:11 dhclient 24262 bound to 146.86.167.83 -- renewal in 302400 seconds.this last entry above is the tail of the log when filtered on "dhclient".
Let me know if this sheds any light on my situation.
I can't tell you how much I appreciate your help!!!
Chuck
-
@cfrudolphy said in New ISP - arpresolve: can't allocate llinfo for X.X.X.X on mvneta0.4090:
Nov 14 22:00:05 dhclient 2500 bound to 146.86.167.83 -- renewal in 302400 seconds.
Ok the first thing I would do here is set a shorter lease request in the dhcp client advanced options. Though it should already request a lease time of 2hrs by default but is being passed am 84hr lease which is very long.
Then it looks like the client is closing the connection before the default renewal at 50% of the lease time.
So something like:
Steve
-
You could also try in the 'option modifiers' field something like:
supersede dhcp-renewal-time 3600So the client renews the lease every hour.
Steve
-
Steve, made all changes you have suggested then released and renewed lease. We will see how it goes and I will let you know. I did go look at the filtered DHCP log and after renewal of lease here is the last line:
Nov 15 18:35:52 dhclient 65046 bound to 146.86.167.83 -- renewal in 1800 seconds.
Yet I did put in as you suggest 3600 as a value not 1800. Even if it renews every 30 minutes as opposed to an hour as long as it doesn't drop then I am ok. Will let you know in the morning.
Thanks much for your help! Have a good evening and I will post again in the morning.
Chuck
-
If you requested a lease time of 3600s and the server gave that you then it would try to renew at 1800s. It should always renew before the lease expires.
Steve
-
@stephenw10 Steve, I am still having issues. Since the changes you suggested, less frequently, but still too much. Beginning to wonder if this is a pfSense issue or an ISP issue. I will try to explain.
Since we added the line "dhcp-lease-time 3600" used the Presets radio button for pfSense Default. It tries to renew the DHCP lease every 1800 seconds (30 minutes) like clock work. Some times it renews and sometimes it doesn't. See this most recent snippet from the log:
Nov 16 14:16:07 dhclient 73086 bound to 146.86.167.83 -- renewal in 1800 seconds.
Nov 16 14:16:07 dhclient Creating resolv.conf
Nov 16 14:16:07 dhclient /sbin/route add default 146.86.160.1
Nov 16 14:16:07 dhclient Adding new routes to interface: mvneta0.4090
Nov 16 14:16:07 dhclient New Routers (mvneta0.4090): 146.86.160.1
Nov 16 14:16:07 dhclient New Broadcast Address (mvneta0.4090): 146.86.167.255
Nov 16 14:16:07 dhclient New Subnet Mask (mvneta0.4090): 255.255.248.0
Nov 16 14:16:07 dhclient New IP Address (mvneta0.4090): 146.86.167.83
Nov 16 14:16:07 dhclient ifconfig mvneta0.4090 inet 146.86.167.83 netmask 255.255.248.0 broadcast 146.86.167.255
Nov 16 14:16:07 dhclient Starting add_new_address()
Nov 16 14:16:07 dhclient BOUND
Nov 16 14:16:07 dhclient 73086 DHCPACK from 146.86.160.3
Nov 16 14:16:07 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 255.255.255.255 port 67
Nov 16 14:16:07 dhclient ARPCHECK
Nov 16 14:16:05 dhclient ARPSEND
Nov 16 14:16:05 dhclient 73086 DHCPOFFER from 146.86.160.3
Nov 16 14:16:05 dhclient 73086 DHCPDISCOVER on mvneta0.4090 to 255.255.255.255 port 67 interval 1
Nov 16 14:16:05 dhclient PREINIT
Nov 16 14:16:05 dhclient Deleting old routes
Nov 16 14:16:05 dhclient EXPIRE
Nov 16 14:15:28 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 255.255.255.255 port 67
Nov 16 14:14:58 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 255.255.255.255 port 67
Nov 16 14:14:13 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 255.255.255.255 port 67
Nov 16 14:13:45 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 255.255.255.255 port 67
Nov 16 14:13:26 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 255.255.255.255 port 67
Nov 16 14:13:12 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 255.255.255.255 port 67
Nov 16 14:12:58 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 255.255.255.255 port 67
Nov 16 14:12:45 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 255.255.255.255 port 67
Nov 16 14:11:57 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 255.255.255.255 port 67
Nov 16 14:11:26 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 255.255.255.255 port 67
Nov 16 14:10:52 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 255.255.255.255 port 67
Nov 16 14:10:34 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 255.255.255.255 port 67
Nov 16 14:10:04 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 255.255.255.255 port 67
Nov 16 14:09:08 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 255.255.255.255 port 67
Nov 16 14:08:25 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 142.202.164.42 port 67
Nov 16 14:08:10 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 142.202.164.42 port 67
Nov 16 14:08:00 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 142.202.164.42 port 67
Nov 16 14:05:55 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 142.202.164.42 port 67
Nov 16 14:03:24 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 142.202.164.42 port 67
Nov 16 14:02:12 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 142.202.164.42 port 67
Nov 16 14:01:29 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 142.202.164.42 port 67
Nov 16 14:01:03 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 142.202.164.42 port 67
Nov 16 14:00:36 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 142.202.164.42 port 67
Nov 16 14:00:28 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 142.202.164.42 port 67
Nov 16 13:59:57 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 142.202.164.42 port 67
Nov 16 13:59:16 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 142.202.164.42 port 67
Nov 16 13:58:40 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 142.202.164.42 port 67
Nov 16 13:57:18 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 142.202.164.42 port 67
Nov 16 13:56:35 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 142.202.164.42 port 67
Nov 16 13:56:08 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 142.202.164.42 port 67
Nov 16 13:55:37 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 142.202.164.42 port 67
Nov 16 13:55:12 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 142.202.164.42 port 67
Nov 16 13:54:49 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 142.202.164.42 port 67
Nov 16 13:54:14 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 142.202.164.42 port 67
Nov 16 13:53:06 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 142.202.164.42 port 67
Nov 16 13:52:08 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 142.202.164.42 port 67
Nov 16 13:51:36 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 142.202.164.42 port 67
Nov 16 13:51:15 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 142.202.164.42 port 67
Nov 16 13:50:58 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 142.202.164.42 port 67
Nov 16 13:50:20 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 142.202.164.42 port 67
Nov 16 13:49:25 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 142.202.164.42 port 67
Nov 16 13:48:30 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 142.202.164.42 port 67
Nov 16 13:47:42 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 142.202.164.42 port 67
Nov 16 13:47:17 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 142.202.164.42 port 67
Nov 16 13:47:03 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 142.202.164.42 port 67
Nov 16 13:46:49 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 142.202.164.42 port 67
Nov 16 13:46:25 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 142.202.164.42 port 67
Nov 16 13:46:14 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 142.202.164.42 port 67
Nov 16 13:46:09 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 142.202.164.42 port 67
Nov 16 13:46:06 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 142.202.164.42 port 67
Nov 16 13:46:04 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 142.202.164.42 port 67
Nov 16 13:16:04 dhclient 73086 bound to 146.86.167.83 -- renewal in 1800 seconds.
Nov 16 13:16:04 dhclient Creating resolv.conf
Nov 16 13:16:04 dhclient RENEW
Nov 16 13:16:04 dhclient 73086 DHCPACK from 142.202.164.42
Nov 16 13:16:04 dhclient 73086 DHCPREQUEST on mvneta0.4090 to 142.202.164.42 port 67
Nov 16 12:46:05 dhclient 68827 bound to 146.86.167.83 -- renewal in 1800 seconds.My summary of the above:
1.) As you can see from the above the lease was renewed at 12:46:05 for 1800 seconds.
2.) It started the renewal process again at 13:16:04 and was successful.
3.) It started the renewal process again at 13:46:04. Between 13:46:04 and 14:15:28 (1764 seconds) it made 51 requests to 142.202.164.42 port 67 (I know that this IP represents the ISP's DNS server don't know about DHCP) but requests to this IP in the past (13:16:04) worked. Then at 14:15:28 it "EXPIRED".
4.) At 14:16:05 I went to Status -> Interfaces then under WAN clicked the button to "Release" and confirmed and then clicked the button to "Renew" and confirmed.
5.) It then sent a discover packet to 255.255.255.255 received an offer fro 146.86.160.3 sent some ARP packets then sent a request, received an acknowledgement, and then renewed the lease.Based on the above sequence of events I have the following questions:
1.) It worked at 13:16:04 then failed at 13:46:04. Is this a pfSense issue or an ISP issue?
2.) I am confused, approximately 3/4 way through its 51 requests it switched from sending "DHCPREQUEST" packets from 142.202.164.42 to 255.255.255.255. Where at 14:16:05 it send a "DHCPDISCOVER" packet to 255.255.255.255. It makes sense to me to send the "discover" packet to the broadcast address, it does not make sense to me to send a "request" packet to the broadcast address.
3.) Every time I release and renew the lease manually it receives a response from 146.86.160.3 not 142.202.164.42. Within that process it discovers the other router at 146.86.160.1. What is going on here? Why is it requesting a renewal from 142.202.164.42 when 146.86.160.3 seems to be authoritative?
4.) Why when I go through the manual release and renewal process on the Status -> Interface page does it instantly work and when it goes through the automated process of renewing the lease it fails more times than works?Last night after we made our changes I noticed something else. Now that we are on this very regular 30 minute lease renewal I was able to very consistently predict what time it should renew. If that process failed then I would lose connectivity at that 30 minute interval. Sometimes I was losing that connectivity prior to the 30 minutes. I started looking at the ARP table at Diagnostics -> ARP Table. I don't know what the starting value of the timer is but I suspect 1200 seconds. I would use the remaining time left on the timer to predict when it would renew and sure enough very close to the calculated time I would lose connectivity. At that point I looked at the "System -> General" log and would see corresponding arpresolve messages.
That leads me to believe the following:
1.) DHCP lease renewal times are in no way co-ordinated with the ARP table timer.
2.) Failure at either causes pfSense to consider the interface "down" for a lack of a better term severing connectivity.
3.) If I had a fail-over wan setup it would then it would go through its process of directing traffic to the fail-over. As I don't have a failover available/setup and I have disabled the "Gateway Monitoring Action" what would the default now be?Note my current configuration is as follows:
System -> Routing -> Gateways
Interface: WAN
Address Family: IPV4
Name: WAN_DHCP
Gateway: Dynamic
Disable Gateway Monitoring Action: Checked
Monitor IP: 8.8.8.8 (As 146.86.160.1 doesn't respond to ping)
ADVANCED
Weight: 1
Data Payload: 1
Latency Thresholds: 200
Packet Loss Thresholds: 10
Probe Interval: 500
Time Period: 60000
Alert Interval: 1000Then in:
Interface -> WAN
Enable: Checked
Description: WAN
IPV4 Configuration Type: DHCP
IPV6 Configuration Type: None
Switch Port: 3
OPTIONS
Advanced Configuration: Checked
Protocol Timing:
TimeOut: 60
Retry: 15
Select Timeout: 0
Reboot: blank
Backoff Cutoff: blank
Initial Interval: 1
Presets: pfSense Default (radio button selected)
Send Options: dhcp-lease-time 3600
Block Private Networks: Checked
Block Bogon Networks: CheckedLong post, lots of info, I hope some of it might be useful in troubleshooting this. I tried to be as complete as I could. I hope it is not to verbose.
Let me know what you think is going on.
Thanks so much for your help!!!
Chuck
-
Yeah it's odd. What the ISP is doing is at the very least unusual!
It tries to renew the lease against the existing dhcp server at it's known IP and then switches to broadcasting for the dhcp server. I'd guess it does that 5mins before the lease expires.
I'm unsure why it doesn't switch to trying to discover any dhcp server at that point. It might be possible to configure that via a dhclient option. I have never had to though.
Switching from an 84 hour lease to 1 hour might have been a little extreme. You might try a 6 or 12h lease and see if that makes any difference there.
Steve
-
Hello, I have a Netgate 1541 and I have the exact same problem happening with my ISP. Was there ever a resolution to this?
Thanks
-
@dragonfire1119 no there was never a resolution. I tried to work with the ISP and they were of no help. I ended up having to rent one of their routers to be able to access the internet. My ISP is an electric utility that ran fiber to our neighborhood. I wanted to get away from Suddenlink (Altice) my previous ISP. Even paying the additional $10 for their router (Calis) it is still cheaper than before with symmetrical bandwidth. That is my story.
-
This post is deleted! -
@cfrudolphy thanks for the reply. We ended up calling and requesting a level 2 they said they had enough calls on level 1 which is a lot of calls to go to level 2. He fixed it on the first try. It's been working great hooked up to Calix ONT > pfsense.
Level 1 was blaming our equipment but this guy did not & actually listened to our problem which was on their end. We worked on this for 3 weeks and calling in constantly. This was some kind of DDoS attack coming through on that VLAN maybe? But the level 3s are going to have to look at it on their end.
Solution:
Switched to a static IP and to a different VLAN on their network.I would try to call in and ask for a level 2.
