I’ve been dabbling with pfSense for a number of years, dating back to 1.2.3. It’s a powerful open source firewall developed here in Austin TX 🙂 Recently I have made the effort to upgrade my old trusty 1.2.3 unit and I ran into some trouble. This is background on my experiences, and what I noted / how I worked around AT&T’s insane DHCP renewal policy.
Production hardware
Intel(R) Atom(TM) CPU D510 @ 1.66GHz
4 CPUs: 1 package(s) x 2 core(s) x 2 HTT threads
4GB USB key (version 1)
120GB SSD (version 2, snort)
Issue log
This is more for me than you 🙂 I’ve had a long history of forgetting how I fixed stuff late at night, so I’ve taken to jotting down notes in a post to have a history of what changes I have applied.
Booting to USB
https://doc.pfsense.org/index.php/Install_pfSense_nanobsd_2.0_to_thumb_drive
/etc/rc.conf_mount_rw
echo kern.cam.boot_delay=10000 >> /boot/loader.conf.local
/etc/rc.conf_mount_ro
DHCP issues with short leases
I never solved this one directly – I was using a DLink DSL-2320B modem in bridge mode. Following an upgrade from 1.2.3 to 2.1.5 I lost connectivity to the Internet. This problem appeared to impact all 2.x releases I tested. I searched around extensively and found these links:
https://forum.pfsense.org/index.php?topic=42777.0
https://forum.pfsense.org/index.php?topic=31208.0
I ended up posting my issue to the pfsense forum:
https://forum.pfsense.org/index.php?topic=85931.0
Ultimately I solved the problem by replacing the DLink modem in bridged mode with a straight up PPPoE modem (TP-Link TD-8616 ADSL2+ Modem) that managed the connection directly from pfSense.
pfSense 1.2.3 – ATT DSL
no issues with connection:
[code]
Dec 22 18:33:29 dhclient[61152]: DHCPREQUEST on em1 to 192.168.1.1 port 67
Dec 22 18:33:29 dhclient[61152]: SENDING DIRECT
Dec 22 18:33:29 dhclient[61152]: DHCPACK from 192.168.1.1
Dec 22 18:33:29 dhclient[61152]: bound to 75.44.28.241 — renewal in 30 seconds.
Dec 22 18:33:59 dhclient[61152]: DHCPREQUEST on em1 to 192.168.1.1 port 67
Dec 22 18:33:59 dhclient[61152]: SENDING DIRECT
Dec 22 18:33:59 dhclient[61152]: DHCPACK from 192.168.1.1
Dec 22 18:33:59 dhclient[61152]: bound to 75.44.28.241 — renewal in 30 seconds.
Dec 22 18:34:29 dhclient[61152]: DHCPREQUEST on em1 to 192.168.1.1 port 67
Dec 22 18:34:29 dhclient[61152]: SENDING DIRECT
Dec 22 18:34:29 dhclient[61152]: DHCPACK from 192.168.1.1
Dec 22 18:34:29 dhclient[61152]: bound to 75.44.28.241 — renewal in 30 seconds.
Dec 22 18:34:59 dhclient[61152]: DHCPREQUEST on em1 to 192.168.1.1 port 67
Dec 22 18:34:59 dhclient[61152]: SENDING DIRECT
Dec 22 18:34:59 dhclient[61152]: DHCPACK from 192.168.1.1
Dec 22 18:34:59 dhclient[61152]: bound to 75.44.28.241 — renewal in 30 seconds.
Dec 22 18:35:29 dhclient[61152]: DHCPREQUEST on em1 to 192.168.1.1 port 67
Dec 22 18:35:29 dhclient[61152]: SENDING DIRECT
Dec 22 18:35:29 dhclient[61152]: DHCPACK from 192.168.1.1
Dec 22 18:35:29 dhclient[61152]: bound to 75.44.28.241 — renewal in 30 seconds.
Dec 22 18:36:00 dhclient[61152]: DHCPREQUEST on em1 to 192.168.1.1 port 67
Dec 22 18:36:00 dhclient[61152]: SENDING DIRECT
Dec 22 18:36:00 dhclient[61152]: DHCPACK from 192.168.1.1
Dec 22 18:36:00 dhclient[61152]: bound to 75.44.28.241 — renewal in 30 seconds.
Dec 22 18:36:30 dhclient[61152]: DHCPREQUEST on em1 to 192.168.1.1 port 67
Dec 22 18:36:30 dhclient[61152]: SENDING DIRECT
Dec 22 18:36:30 dhclient[61152]: DHCPACK from 192.168.1.1
Dec 22 18:36:30 dhclient[61152]: bound to 75.44.28.241 — renewal in 30 seconds.
Dec 22 18:37:00 dhclient[61152]: DHCPREQUEST on em1 to 192.168.1.1 port 67
Dec 22 18:37:00 dhclient[61152]: SENDING DIRECT
Dec 22 18:37:00 dhclient[61152]: DHCPACK from 192.168.1.1
Dec 22 18:37:01 dhclient[61152]: bound to 75.44.28.241 — renewal in 30 seconds.
[/code]
pfSense 2.1.5 with AT&T DSL
Also true with 2.1.4 amd64, 2.0.3 amd64, 2.1.5 amd64 LiveCD with installer, 2.1.5 i386,
General log
[code]
Dec 24 04:17:45 check_reload_status: rc.newwanip starting em1
Dec 24 04:17:47 php: rc.newwanip: rc.newwanip: Informational is starting em1.
Dec 24 04:17:47 php: rc.newwanip: rc.newwanip: on (IP address: 111.111.111.111) (interface: WAN[wan]) (real interface: em1).
Dec 24 04:17:47 php: rc.newwanip: ROUTING: setting default route to 75.44.28.1
Dec 24 04:17:52 php: rc.newwanip: Resyncing OpenVPN instances for interface WAN.
Dec 24 04:17:52 php: rc.newwanip: Creating rrd update script
Dec 24 04:17:54 php: rc.newwanip: pfSense package system has detected an ip change 111.111.111.111 -> 75.44.28.241 … Restarting packages.
Dec 24 04:17:54 check_reload_status: Starting packages
Dec 24 04:17:54 check_reload_status: Reloading filter
Dec 24 04:17:57 php: rc.start_packages: Restarting/Starting all packages.
Dec 24 04:21:40 check_reload_status: rc.newwanip starting em1
Dec 24 04:21:43 php: rc.newwanip: rc.newwanip: Informational is starting em1.
Dec 24 04:21:43 php: rc.newwanip: rc.newwanip: on (IP address: 111.111.111.111) (interface: WAN[wan]) (real interface: em1).
Dec 24 04:21:43 php: rc.newwanip: ROUTING: setting default route to 75.44.28.1
Dec 24 04:21:48 php: rc.newwanip: Resyncing OpenVPN instances for interface WAN.
Dec 24 04:21:48 php: rc.newwanip: Creating rrd update script
Dec 24 04:21:50 php: rc.newwanip: pfSense package system has detected an ip change 111.111.111.111 -> 75.44.28.241 … Restarting packages.
Dec 24 04:21:50 check_reload_status: Starting packages
Dec 24 04:21:50 check_reload_status: Reloading filter
Dec 24 04:21:53 php: rc.start_packages: Restarting/Starting all packages.
Dec 24 04:22:43 check_reload_status: rc.newwanip starting em1
Dec 24 04:22:45 php: rc.newwanip: rc.newwanip: Informational is starting em1.
Dec 24 04:22:45 php: rc.newwanip: rc.newwanip: on (IP address: 111.111.111.111) (interface: WAN[wan]) (real interface: em1).
Dec 24 04:22:45 php: rc.newwanip: ROUTING: setting default route to 75.44.28.1
Dec 24 04:22:50 php: rc.newwanip: Resyncing OpenVPN instances for interface WAN.
Dec 24 04:22:50 php: rc.newwanip: Creating rrd update script
Dec 24 04:22:52 php: rc.newwanip: pfSense package system has detected an ip change 111.111.111.111 -> 75.44.28.241 … Restarting packages.
Dec 24 04:22:52 check_reload_status: Starting packages
Dec 24 04:22:52 check_reload_status: Reloading filter
Dec 24 04:22:55 php: rc.start_packages: Restarting/Starting all packages.
Dec 24 04:23:46 check_reload_status: rc.newwanip starting em1
Dec 24 04:23:49 php: rc.newwanip: rc.newwanip: Informational is starting em1.
Dec 24 04:23:49 php: rc.newwanip: rc.newwanip: on (IP address: 111.111.111.111) (interface: WAN[wan]) (real interface: em1).
Dec 24 04:23:49 php: rc.newwanip: ROUTING: setting default route to 75.44.28.1
Dec 24 04:23:54 php: rc.newwanip: Resyncing OpenVPN instances for interface WAN.
Dec 24 04:23:54 php: rc.newwanip: Creating rrd update script
Dec 24 04:23:56 php: rc.newwanip: pfSense package system has detected an ip change 111.111.111.111 -> 111.111.111.111 … Restarting packages.
Dec 24 04:23:56 check_reload_status: Starting packages
Dec 24 04:23:56 check_reload_status: Reloading filter
Dec 24 04:23:58 php: rc.start_packages: Restarting/Starting all packages.
Dec 24 04:28:34 check_reload_status: rc.newwanip starting em1
Dec 24 04:28:37 php: rc.newwanip: rc.newwanip: Informational is starting em1.
Dec 24 04:28:37 php: rc.newwanip: rc.newwanip: on (IP address: 111.111.111.111) (interface: WAN[wan]) (real interface: em1).
Dec 24 04:28:37 php: rc.newwanip: ROUTING: setting default route to 75.44.28.1
Dec 24 04:28:42 php: rc.newwanip: Resyncing OpenVPN instances for interface WAN.
Dec 24 04:28:42 php: rc.newwanip: Creating rrd update script
Dec 24 04:28:44 php: rc.newwanip: pfSense package system has detected an ip change 111.111.111.111 -> 75.44.28.241 … Restarting packages.
Dec 24 04:28:44 check_reload_status: Starting packages
Dec 24 04:28:44 check_reload_status: Reloading filter
Dec 24 04:28:47 php: rc.start_packages: Restarting/Starting all packages.
[/code]
Gateways log
[code]
Dec 24 04:11:49 apinger: SIGHUP received, reloading configuration.
Dec 24 04:11:54 apinger: SIGHUP received, reloading configuration.
Dec 24 04:12:51 apinger: SIGHUP received, reloading configuration.
Dec 24 04:13:54 apinger: SIGHUP received, reloading configuration.
Dec 24 04:17:47 apinger: SIGHUP received, reloading configuration.
Dec 24 04:21:43 apinger: SIGHUP received, reloading configuration.
Dec 24 04:22:45 apinger: SIGHUP received, reloading configuration.
Dec 24 04:23:49 apinger: SIGHUP received, reloading configuration.
Dec 24 04:28:37 apinger: SIGHUP received, reloading configuration.
Dec 24 04:30:36 apinger: SIGHUP received, reloading configuration.
Dec 24 04:31:39 apinger: SIGHUP received, reloading configuration.
Dec 24 04:32:42 apinger: SIGHUP received, reloading configuration.
Dec 24 04:33:45 apinger: SIGHUP received, reloading configuration.
Dec 24 04:39:32 apinger: SIGHUP received, reloading configuration.
Dec 24 04:41:28 apinger: SIGHUP received, reloading configuration.
[/code]
Resolver log
[code]
Dec 24 04:12:58 dnsmasq[92184]: using nameserver 8.8.8.8#53
Dec 24 04:12:58 dnsmasq[92184]: using nameserver 8.8.4.4#53
Dec 24 04:13:56 dnsmasq[92184]: reading /etc/resolv.conf
Dec 24 04:13:56 dnsmasq[92184]: ignoring nameserver 127.0.0.1 – local interface
Dec 24 04:13:56 dnsmasq[92184]: using nameserver 8.8.8.8#53
Dec 24 04:13:56 dnsmasq[92184]: using nameserver 8.8.4.4#53
Dec 24 04:17:50 dnsmasq[92184]: reading /etc/resolv.conf
Dec 24 04:17:50 dnsmasq[92184]: ignoring nameserver 127.0.0.1 – local interface
Dec 24 04:17:50 dnsmasq[92184]: using nameserver 8.8.8.8#53
Dec 24 04:17:50 dnsmasq[92184]: using nameserver 8.8.4.4#53
Dec 24 04:21:43 dnsmasq[92184]: reading /etc/resolv.conf
Dec 24 04:21:43 dnsmasq[92184]: ignoring nameserver 127.0.0.1 – local interface
Dec 24 04:21:43 dnsmasq[92184]: using nameserver 8.8.8.8#53
Dec 24 04:21:43 dnsmasq[92184]: using nameserver 8.8.4.4#53
Dec 24 04:22:45 dnsmasq[92184]: reading /etc/resolv.conf
Dec 24 04:22:45 dnsmasq[92184]: ignoring nameserver 127.0.0.1 – local interface
Dec 24 04:22:45 dnsmasq[92184]: using nameserver 8.8.8.8#53
Dec 24 04:22:45 dnsmasq[92184]: using nameserver 8.8.4.4#53
Dec 24 04:23:49 dnsmasq[92184]: reading /etc/resolv.conf
Dec 24 04:23:49 dnsmasq[92184]: ignoring nameserver 127.0.0.1 – local interface
Dec 24 04:23:49 dnsmasq[92184]: using nameserver 8.8.8.8#53
Dec 24 04:23:49 dnsmasq[92184]: using nameserver 8.8.4.4#53
Dec 24 04:28:53 dnsmasq[92184]: reading /etc/resolv.conf
Dec 24 04:28:53 dnsmasq[92184]: ignoring nameserver 127.0.0.1 – local interface
Dec 24 04:28:53 dnsmasq[92184]: using nameserver 8.8.8.8#53
Dec 24 04:28:53 dnsmasq[92184]: using nameserver 8.8.4.4#53
Dec 24 04:30:36 dnsmasq[92184]: reading /etc/resolv.conf
Dec 24 04:30:36 dnsmasq[92184]: ignoring nameserver 127.0.0.1 – local interface
Dec 24 04:30:36 dnsmasq[92184]: using nameserver 8.8.8.8#53
Dec 24 04:30:36 dnsmasq[92184]: using nameserver 8.8.4.4#53
Dec 24 04:31:39 dnsmasq[92184]: reading /etc/resolv.conf
Dec 24 04:31:39 dnsmasq[92184]: ignoring nameserver 127.0.0.1 – local interface
Dec 24 04:31:39 dnsmasq[92184]: using nameserver 8.8.8.8#53
Dec 24 04:31:39 dnsmasq[92184]: using nameserver 8.8.4.4#53
Dec 24 04:32:43 dnsmasq[92184]: reading /etc/resolv.conf
Dec 24 04:32:43 dnsmasq[92184]: ignoring nameserver 127.0.0.1 – local interface
Dec 24 04:32:43 dnsmasq[92184]: using nameserver 8.8.8.8#53
Dec 24 04:32:43 dnsmasq[92184]: using nameserver 8.8.4.4#53
Dec 24 04:33:45 dnsmasq[92184]: reading /etc/resolv.conf
Dec 24 04:33:45 dnsmasq[92184]: ignoring nameserver 127.0.0.1 – local interface
Dec 24 04:33:45 dnsmasq[92184]: using nameserver 8.8.8.8#53
Dec 24 04:33:45 dnsmasq[92184]: using nameserver 8.8.4.4#53
Dec 24 04:39:32 dnsmasq[92184]: reading /etc/resolv.conf
Dec 24 04:39:32 dnsmasq[92184]: ignoring nameserver 127.0.0.1 – local interface
Dec 24 04:39:32 dnsmasq[92184]: using nameserver 8.8.8.8#53
Dec 24 04:39:32 dnsmasq[92184]: using nameserver 8.8.4.4#53
Dec 24 04:41:28 dnsmasq[92184]: reading /etc/resolv.conf
Dec 24 04:41:28 dnsmasq[92184]: ignoring nameserver 127.0.0.1 – local interface
Dec 24 04:41:28 dnsmasq[92184]: using nameserver 8.8.8.8#53
Dec 24 04:41:28 dnsmasq[92184]: using nameserver 8.8.4.4#53
[/code]
DHCP log
[code]
Dec 24 04:23:46 dhclient: Creating resolv.conf
Dec 24 04:23:46 dhclient[88203]: bound to 111.111.111.111 — renewal in 30 seconds.
Dec 24 04:24:16 dhclient[88203]: DHCPREQUEST on em1 to 192.168.1.1 port 67
Dec 24 04:24:18 dhclient[88203]: DHCPREQUEST on em1 to 192.168.1.1 port 67
Dec 24 04:24:22 dhclient[88203]: DHCPREQUEST on em1 to 192.168.1.1 port 67
Dec 24 04:24:26 dhclient[88203]: DHCPREQUEST on em1 to 192.168.1.1 port 67
Dec 24 04:24:30 dhclient[88203]: DHCPREQUEST on em1 to 192.168.1.1 port 67
Dec 24 04:24:39 dhclient[88203]: DHCPREQUEST on em1 to 255.255.255.255 port 67
Dec 24 04:24:39 dhclient[88203]: DHCPACK from 192.168.1.1
Dec 24 04:24:39 dhclient: RENEW
Dec 24 04:24:39 dhclient: Creating resolv.conf
Dec 24 04:24:39 dhclient[88203]: bound to 111.111.111.111 — renewal in 30 seconds.
Dec 24 04:24:59 dhcpd: DHCPREQUEST for 10.12.4.93 from 50:e5:49:e7:d2:5d (FELIX) via em0
Dec 24 04:24:59 dhcpd: DHCPACK on 10.12.4.93 to 50:e5:49:e7:d2:5d (FELIX) via em0
Dec 24 04:25:09 dhclient[88203]: DHCPREQUEST on em1 to 192.168.1.1 port 67
Dec 24 04:25:11 dhclient[88203]: DHCPREQUEST on em1 to 192.168.1.1 port 67
Dec 24 04:25:14 dhclient[88203]: DHCPREQUEST on em1 to 192.168.1.1 port 67
Dec 24 04:25:20 dhclient[88203]: DHCPREQUEST on em1 to 192.168.1.1 port 67
Dec 24 04:25:29 dhclient[88203]: DHCPREQUEST on em1 to 192.168.1.1 port 67
Dec 24 04:25:38 dhclient[88203]: DHCPREQUEST on em1 to 255.255.255.255 port 67
Dec 24 04:25:38 dhclient[88203]: DHCPACK from 192.168.1.1
Dec 24 04:25:38 dhclient: RENEW
Dec 24 04:25:38 dhclient: Creating resolv.conf
Dec 24 04:25:38 dhclient[88203]: bound to 111.111.111.111 — renewal in 30 seconds.
Dec 24 04:26:08 dhclient[88203]: DHCPREQUEST on em1 to 192.168.1.1 port 67
Dec 24 04:26:09 dhclient[88203]: DHCPREQUEST on em1 to 192.168.1.1 port 67
Dec 24 04:26:10 dhclient[88203]: DHCPREQUEST on em1 to 192.168.1.1 port 67
Dec 24 04:26:11 dhclient[88203]: DHCPREQUEST on em1 to 192.168.1.1 port 67
Dec 24 04:26:13 dhclient[88203]: DHCPREQUEST on em1 to 192.168.1.1 port 67
Dec 24 04:26:15 dhclient[88203]: DHCPREQUEST on em1 to 192.168.1.1 port 67
Dec 24 04:26:20 dhclient[88203]: DHCPREQUEST on em1 to 192.168.1.1 port 67
Dec 24 04:26:26 dhclient[88203]: DHCPREQUEST on em1 to 192.168.1.1 port 67
Dec 24 04:26:34 dhclient[88203]: DHCPREQUEST on em1 to 255.255.255.255 port 67
Dec 24 04:26:34 dhclient[88203]: DHCPACK from 192.168.1.1
Dec 24 04:26:34 dhclient: RENEW
Dec 24 04:26:34 dhclient: Creating resolv.conf
Dec 24 04:26:34 dhclient[88203]: bound to 111.111.111.111 — renewal in 30 seconds.
Dec 24 04:27:04 dhclient[88203]: DHCPREQUEST on em1 to 192.168.1.1 port 67
Dec 24 04:27:05 dhclient[88203]: DHCPREQUEST on em1 to 192.168.1.1 port 67
Dec 24 04:27:06 dhclient[88203]: DHCPREQUEST on em1 to 192.168.1.1 port 67
Dec 24 04:27:07 dhclient[88203]: DHCPREQUEST on em1 to 192.168.1.1 port 67
Dec 24 04:27:09 dhclient[88203]: DHCPREQUEST on em1 to 192.168.1.1 port 67
Dec 24 04:27:12 dhclient[88203]: DHCPREQUEST on em1 to 192.168.1.1 port 67
Dec 24 04:27:15 dhclient[88203]: DHCPREQUEST on em1 to 192.168.1.1 port 67
Dec 24 04:27:24 dhclient[88203]: DHCPREQUEST on em1 to 192.168.1.1 port 67
Dec 24 04:27:31 dhclient[88203]: DHCPREQUEST on em1 to 255.255.255.255 port 67
Dec 24 04:27:31 dhclient[88203]: DHCPACK from 192.168.1.1
Dec 24 04:27:31 dhclient: RENEW
Dec 24 04:27:31 dhclient: Creating resolv.conf
Dec 24 04:27:31 dhclient[88203]: bound to 111.111.111.111 — renewal in 30 seconds.
[/code]