WAN DHCP IPV4 address gone - can't allocate llinfo



  • The error that came when using Status:Interfaces to release and renew a DHCP address has been fixed -
    http://forum.pfsense.org/index.php/topic,52046.0.html
    Now, the reason that I ended up using this release/renew button was that I had lost the IPV4 address from my WAN interface. It happened to me again today on:
    2.1-BETA0 (i386)
    built on Sun Aug 5 18:24:43 EDT 2012
    FreeBSD 8.3-RELEASE-p3

    I had just installed OpenVPN Client Export Utility on my test system. The test system is an Alix with WAN set to DHCP on an internal subnet. The DHCP server is a pfSense Alix router on the internal subnet running the same 2.1-BETA0 release, and that is the gateway to the real internet. I am not trying to do any IPV6 stuff on either box, the default IPV6 functions that come in 2.1 just happen by themselves, so there are fe80 addresses.

    It seems that something gets mixed up during all the check_reload_status stuff.
    Here is my WAN vr1 when it has the problem (there is no IPV4 setting):

    vr1: flags=8843 <up,broadcast,running,simplex,multicast>metric 0 mtu 1500
            options=8280b <rxcsum,txcsum,vlan_mtu,wol_ucast,wol_magic,linkstate>ether 00:0d:b9:24:58:b5
            inet6 fe80::20d:b9ff:fe24:58b5%vr1 prefixlen 64 scopeid 0x2
            nd6 options=3 <performnud,accept_rtadv>media: Ethernet autoselect (100baseTX <full-duplex>)
            status: active</full-duplex></performnud,accept_rtadv></rxcsum,txcsum,vlan_mtu,wol_ucast,wol_magic,linkstate></up,broadcast,running,simplex,multicast> 
    

    Here it is after clicking release then renew (IPV4 settings are back):

    vr1: flags=8843 <up,broadcast,running,simplex,multicast>metric 0 mtu 1500
            options=8280b <rxcsum,txcsum,vlan_mtu,wol_ucast,wol_magic,linkstate>ether 00:0d:b9:24:58:b5
            inet6 fe80::20d:b9ff:fe24:58b5%vr1 prefixlen 64 scopeid 0x2
            inet 10.49.80.166 netmask 0xffffff00 broadcast 10.49.80.255
            nd6 options=3 <performnud,accept_rtadv>media: Ethernet autoselect (100baseTX <full-duplex>)
            status: active</full-duplex></performnud,accept_rtadv></rxcsum,txcsum,vlan_mtu,wol_ucast,wol_magic,linkstate></up,broadcast,running,simplex,multicast> 
    

    Here is some syslog output:

    Aug  6 14:25:21 test02 check_reload_status: Syncing firewall
    Aug  6 14:25:22 test02 php: /pkg_mgr_install.php: Beginning package installation for OpenVPN Client Export Utility .
    Aug  6 14:26:28 test02 dhclient: RENEW
    Aug  6 14:26:28 test02 dhclient: Creating resolv.conf
    Aug  6 14:30:12 test02 check_reload_status: Syncing firewall
    Aug  6 14:30:15 test02 check_reload_status: Reloading filter
    Aug  6 14:30:16 test02 kernel: vr1: link state changed to DOWN
    Aug  6 14:30:19 test02 kernel: vr1: link state changed to UP
    Aug  6 14:30:24 test02 check_reload_status: Linkup starting vr1
    Aug  6 14:30:25 test02 check_reload_status: Linkup starting vr1
    Aug  6 14:30:31 test02 php: : DEVD Ethernet detached event for wan
    Aug  6 14:30:31 test02 php: : Calling interface down for interface wan, destroy is 
    Aug  6 14:30:31 test02 dhclient[6479]: connection closed
    Aug  6 14:30:31 test02 dhclient[6479]: connection closed
    Aug  6 14:30:31 test02 dhclient[6479]: exiting.
    Aug  6 14:30:31 test02 dhclient[6479]: exiting.
    Aug  6 14:30:31 test02 php: : DEVD Ethernet attached event for wan
    Aug  6 14:30:32 test02 php: : HOTPLUG: Configuring interface wan
    Aug  6 14:30:32 test02 php: : Deny router advertisements for interface wan
    Aug  6 14:30:32 test02 dhclient: PREINIT
    Aug  6 14:30:32 test02 dhclient[25563]: DHCPREQUEST on vr1 to 255.255.255.255 port 67
    Aug  6 14:30:32 test02 dhclient[25563]: DHCPACK from 10.49.80.250
    Aug  6 14:30:32 test02 dhclient: REBOOT
    Aug  6 14:30:32 test02 dhclient: Starting add_new_address()
    Aug  6 14:30:32 test02 dhclient: ifconfig vr1 inet 10.49.80.166 netmask 255.255.255.0 broadcast 10.49.80.255 
    Aug  6 14:30:32 test02 dhclient: New IP Address (vr1): 10.49.80.166
    Aug  6 14:30:32 test02 dhclient: New Subnet Mask (vr1): 255.255.255.0
    Aug  6 14:30:32 test02 dhclient: New Broadcast Address (vr1): 10.49.80.255
    Aug  6 14:30:32 test02 dhclient: New Routers (vr1): 10.49.80.250
    Aug  6 14:30:32 test02 dhclient: Adding new routes to interface: vr1
    Aug  6 14:30:32 test02 dhclient: /sbin/route add default 10.49.80.250
    Aug  6 14:30:32 test02 dhclient: Creating resolv.conf
    Aug  6 14:30:32 test02 dhclient[25563]: bound to 10.49.80.166 -- renewal in 3600 seconds.
    Aug  6 14:30:32 test02 php: : setting up lan - 0
    Aug  6 14:30:32 test02 check_reload_status: rc.newwanip starting vr1
    Aug  6 14:30:32 test02 dhcp6c[13846]: check_exit: exiting
    Aug  6 14:30:33 test02 php: : Accept router advertisements on interface vr1 
    Aug  6 14:30:33 test02 check_reload_status: Reloading filter
    Aug  6 14:30:36 test02 dhcp6c[35281]: dhcp6_ctl_authinit: failed to open /usr/local/etc/dhcp6cctlkey: No such file or directory
    Aug  6 14:30:36 test02 dhcp6c[35281]: dhcp6_ctl_authinit: failed to open /usr/local/etc/dhcp6cctlkey: No such file or directory
    Aug  6 14:30:36 test02 dhcp6c[35281]: client6_init: failed initialize control message authentication
    Aug  6 14:30:36 test02 dhcp6c[35281]: client6_init: failed initialize control message authentication
    Aug  6 14:30:36 test02 dhcp6c[35281]: client6_init: skip opening control port
    Aug  6 14:30:36 test02 dhcp6c[35281]: client6_init: skip opening control port
    Aug  6 14:30:36 test02 dhcp6c[35281]: cfparse: cfparse: fopen(/var/etc/dhcp6c_wan.conf): No such file or directory
    Aug  6 14:30:36 test02 dhcp6c[35281]: cfparse: cfparse: fopen(/var/etc/dhcp6c_wan.conf): No such file or directory
    Aug  6 14:30:36 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  6 14:30:39 test02 php: : rc.newwanip: Informational is starting vr1.
    Aug  6 14:30:39 test02 php: : rc.newwanip: on (IP address: ) (interface: wan) (real interface: vr1).
    Aug  6 14:30:39 test02 php: : rc.newwanip: Failed to update wan IP, restarting...
    Aug  6 14:30:39 test02 check_reload_status: Configuring interface wan
    Aug  6 14:30:40 test02 php: : Could not find IPv4 gateway for interface (wan).
    Aug  6 14:30:41 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  6 14:30:44 test02 php: : Deny router advertisements for interface wan
    Aug  6 14:30:44 test02 dhclient[39507]: dhclient already running, pid: 34230.
    Aug  6 14:30:44 test02 dhclient[39507]: dhclient already running, pid: 34230.
    Aug  6 14:30:44 test02 dhclient[39507]: exiting.
    Aug  6 14:30:44 test02 dhclient[39507]: exiting.
    Aug  6 14:30:44 test02 php: : The command '/sbin/dhclient -c /var/etc/dhclient_wan.conf vr1 > /tmp/vr1_output > /tmp/vr1_error_output' returned exit code '1', the output was '' 
    Aug  6 14:30:44 test02 php: : setting up lan - 0
    Aug  6 14:30:44 test02 php: : Accept router advertisements on interface vr1 
    Aug  6 14:30:44 test02 check_reload_status: Reloading filter
    Aug  6 14:30:46 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  6 14:30:47 test02 php: : Interface lan configured via wan  type dhcp6
    Aug  6 14:30:47 test02 dhcp6c[40455]: dhcp6_ctl_authinit: failed to open /usr/local/etc/dhcp6cctlkey: No such file or directory
    Aug  6 14:30:47 test02 dhcp6c[40455]: dhcp6_ctl_authinit: failed to open /usr/local/etc/dhcp6cctlkey: No such file or directory
    Aug  6 14:30:47 test02 dhcp6c[40455]: client6_init: failed initialize control message authentication
    Aug  6 14:30:47 test02 dhcp6c[40455]: client6_init: failed initialize control message authentication
    Aug  6 14:30:47 test02 dhcp6c[40455]: client6_init: skip opening control port
    Aug  6 14:30:47 test02 dhcp6c[40455]: client6_init: skip opening control port
    Aug  6 14:30:50 test02 php: : Could not find IPv4 gateway for interface (wan).
    Aug  6 14:30:51 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  6 14:30:56 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  6 14:30:57 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  6 14:30:58 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  6 14:30:58 test02 php: : Interface lan configured via wan  type dhcp6
    Aug  6 14:30:58 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  6 14:30:59 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  6 14:31:00 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  6 14:31:01 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  6 14:31:02 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  6 14:31:04 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  6 14:31:04 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  6 14:31:05 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  6 14:31:06 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  6 14:31:06 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  6 14:31:07 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  6 14:31:08 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  6 14:31:08 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  6 14:31:08 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  6 14:31:09 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  6 14:31:11 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  6 14:31:11 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  6 14:31:12 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  6 14:31:13 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  6 14:31:16 test02 check_reload_status: Updating all dyndns
    Aug  6 14:31:16 test02 check_reload_status: Restarting ipsec tunnels
    Aug  6 14:31:16 test02 check_reload_status: Reloading filter
    Aug  6 14:31:16 test02 check_reload_status: Restarting OpenVPN tunnels/interfaces
    Aug  6 14:31:16 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  6 14:31:18 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  6 14:31:18 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  6 14:31:19 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  6 14:31:20 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  6 14:31:21 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  6 14:31:21 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  6 14:31:22 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  6 14:31:24 test02 php: : Resyncing OpenVPN instances.
    Aug  6 14:31:25 test02 php: : DynDns: updatedns() starting
    Aug  6 14:31:25 test02 php: : running get_failover_interface for wan. found vr1
    Aug  6 14:31:25 test02 php: : There was an error trying to determine the public IP for interface - wan(vr1). Probably interface is not a WAN interface.
    Aug  6 14:31:25 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  6 14:31:26 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  6 14:31:26 test02 php: : Could not find IPv4 gateway for interface (wan).
    Aug  6 14:31:26 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  6 14:31:27 test02 check_reload_status: Reloading filter
    Aug  6 14:31:33 test02 php: : Could not find IPv4 gateway for interface (wan).
    
    

    "can't allocate llinfo for 10.49.80.250" seems to be the where it gets into trouble.
    I don't know if the client6_init and cfparse errors (stuff related to IPV6) cause problems either?
    This llinfo message gets a mention in these 2.1 posts and some other 2.0.n posts:
    http://forum.pfsense.org/index.php/topic,52263.0.html - WAN Interfaces down (static ones!)
    http://forum.pfsense.org/index.php/topic,46738.0.html - a BridgeGW issue
    http://forum.pfsense.org/index.php/topic,49811.0.html - arpresolv error and WAN NIC down

    I have had this problem happen a couple of times in the last week or so on different builds, since changing to using DHCP on my test box WAN interface.



  • I upgraded to:
    2.1-BETA0 (i386)
    built on Tue Aug 7 18:18:58 EDT 2012
    FreeBSD 8.3-RELEASE-p4

    I have a production pfSense nanobsd on my real internet connection. Then on the internal LAN is my test nanobsd system's WAN port, which uses DHCP to get an internal LAN address and learn the gateway etc out to the real internet. Both systems are on the above snapshot.

    I saw that Jim had committed https://github.com/bsdperimeter/pfsense-tools/commit/a5367b9f28b4c92f37fc99bf60a0b51c74c7a097 with some makefile change for dhcp server. So I thought that maybe this might change the behaviour between DHCP server and client.

    But my test system WAN IPV4 address went AWOL again today. Had to use Status:Interfaces release/renew button to get it back. I can also get it back by physically disconnecting and reconnecting the WAN cable (I guess that triggers lots of software stuff, including trying to DHCP again).

    The DHCP server log on the production system has nothing odd - it simply gives out/renews the address each hour as the requests come in.

    The test system DHCP client seems to be the thing that runs into trouble. Here is a chunk of system.log:

    Aug  9 13:41:48 test02 dhclient: RENEW
    Aug  9 13:41:48 test02 dhclient: Creating resolv.conf
    Aug  9 14:41:49 test02 dhclient: RENEW
    Aug  9 14:41:49 test02 dhclient: Creating resolv.conf
    Aug  9 14:47:47 test02 check_reload_status: Linkup starting vr1
    Aug  9 14:47:47 test02 kernel: vr1: link state changed to DOWN
    Aug  9 14:47:49 test02 check_reload_status: Linkup starting vr1
    Aug  9 14:47:49 test02 kernel: vr1: link state changed to UP
    Aug  9 14:47:51 test02 php: : DEVD Ethernet detached event for wan
    Aug  9 14:47:51 test02 php: : Calling interface down for interface wan, destroy is 
    Aug  9 14:47:51 test02 dhclient[6776]: connection closed
    Aug  9 14:47:51 test02 dhclient[6776]: connection closed
    Aug  9 14:47:52 test02 dhclient[6776]: exiting.
    Aug  9 14:47:52 test02 dhclient[6776]: exiting.
    Aug  9 14:47:53 test02 dhcp6c[12833]: check_exit: exiting
    Aug  9 14:47:54 test02 php: : DEVD Ethernet attached event for wan
    Aug  9 14:47:54 test02 php: : HOTPLUG: Configuring interface wan
    Aug  9 14:47:54 test02 php: : Deny router advertisements for interface wan
    Aug  9 14:47:54 test02 dhclient: PREINIT
    Aug  9 14:47:54 test02 dhclient[45964]: DHCPREQUEST on vr1 to 255.255.255.255 port 67
    Aug  9 14:47:54 test02 dhclient[45964]: DHCPACK from 10.49.80.250
    Aug  9 14:47:54 test02 dhclient: REBOOT
    Aug  9 14:47:54 test02 dhclient: Starting add_new_address()
    Aug  9 14:47:54 test02 dhclient: ifconfig vr1 inet 10.49.80.166 netmask 255.255.255.0 broadcast 10.49.80.255 
    Aug  9 14:47:54 test02 dhclient: New IP Address (vr1): 10.49.80.166
    Aug  9 14:47:54 test02 dhclient: New Subnet Mask (vr1): 255.255.255.0
    Aug  9 14:47:54 test02 dhclient: New Broadcast Address (vr1): 10.49.80.255
    Aug  9 14:47:54 test02 dhclient: New Routers (vr1): 10.49.80.250
    Aug  9 14:47:54 test02 dhclient: Adding new routes to interface: vr1
    Aug  9 14:47:54 test02 dhclient: /sbin/route add default 10.49.80.250
    Aug  9 14:47:54 test02 dhclient: Creating resolv.conf
    Aug  9 14:47:55 test02 dhclient[45964]: bound to 10.49.80.166 -- renewal in 3600 seconds.
    Aug  9 14:47:55 test02 check_reload_status: rc.newwanip starting vr1
    Aug  9 14:47:55 test02 php: : setting up lan - 0
    Aug  9 14:47:55 test02 php: : Accept router advertisements on interface vr1 
    Aug  9 14:47:55 test02 check_reload_status: Reloading filter
    Aug  9 14:47:56 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  9 14:47:58 test02 dhcp6c[59614]: dhcp6_ctl_authinit: failed to open /usr/local/etc/dhcp6cctlkey: No such file or directory
    Aug  9 14:47:58 test02 dhcp6c[59614]: dhcp6_ctl_authinit: failed to open /usr/local/etc/dhcp6cctlkey: No such file or directory
    Aug  9 14:47:58 test02 dhcp6c[59614]: client6_init: failed initialize control message authentication
    Aug  9 14:47:58 test02 dhcp6c[59614]: client6_init: failed initialize control message authentication
    Aug  9 14:47:58 test02 dhcp6c[59614]: client6_init: skip opening control port
    Aug  9 14:47:58 test02 dhcp6c[59614]: client6_init: skip opening control port
    Aug  9 14:47:58 test02 dhcp6c[59614]: cfparse: cfparse: fopen(/var/etc/dhcp6c_wan.conf): No such file or directory
    Aug  9 14:47:58 test02 dhcp6c[59614]: cfparse: cfparse: fopen(/var/etc/dhcp6c_wan.conf): No such file or directory
    Aug  9 14:48:01 test02 php: : rc.newwanip: Informational is starting vr1.
    Aug  9 14:48:01 test02 php: : rc.newwanip: on (IP address: ) (interface: wan) (real interface: vr1).
    Aug  9 14:48:01 test02 php: : rc.newwanip: Failed to update wan IP, restarting...
    Aug  9 14:48:01 test02 check_reload_status: Configuring interface wan
    Aug  9 14:48:01 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  9 14:48:02 test02 php: : Could not find IPv4 gateway for interface (wan).
    Aug  9 14:48:06 test02 php: : Deny router advertisements for interface wan
    Aug  9 14:48:06 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  9 14:48:06 test02 dhclient[9054]: dhclient already running, pid: 58767.
    Aug  9 14:48:06 test02 dhclient[9054]: dhclient already running, pid: 58767.
    Aug  9 14:48:06 test02 dhclient[9054]: exiting.
    Aug  9 14:48:06 test02 dhclient[9054]: exiting.
    Aug  9 14:48:06 test02 php: : The command '/sbin/dhclient -c /var/etc/dhclient_wan.conf vr1 > /tmp/vr1_output > /tmp/vr1_error_output' returned exit code '1', the output was '' 
    Aug  9 14:48:06 test02 php: : setting up lan - 0
    Aug  9 14:48:06 test02 php: : Accept router advertisements on interface vr1 
    Aug  9 14:48:06 test02 check_reload_status: Reloading filter
    Aug  9 14:48:09 test02 php: : Interface lan configured via wan  type dhcp6
    Aug  9 14:48:09 test02 dhcp6c[22591]: dhcp6_ctl_authinit: failed to open /usr/local/etc/dhcp6cctlkey: No such file or directory
    Aug  9 14:48:09 test02 dhcp6c[22591]: dhcp6_ctl_authinit: failed to open /usr/local/etc/dhcp6cctlkey: No such file or directory
    Aug  9 14:48:09 test02 dhcp6c[22591]: client6_init: failed initialize control message authentication
    Aug  9 14:48:09 test02 dhcp6c[22591]: client6_init: failed initialize control message authentication
    Aug  9 14:48:09 test02 dhcp6c[22591]: client6_init: skip opening control port
    Aug  9 14:48:09 test02 dhcp6c[22591]: client6_init: skip opening control port
    Aug  9 14:48:11 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  9 14:48:13 test02 php: : Could not find IPv4 gateway for interface (wan).
    Aug  9 14:48:16 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  9 14:48:17 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  9 14:48:18 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  9 14:48:19 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  9 14:48:20 test02 php: : Interface lan configured via wan  type dhcp6
    Aug  9 14:48:21 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  9 14:48:22 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  9 14:48:25 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  9 14:48:26 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  9 14:48:28 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  9 14:48:29 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  9 14:48:30 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  9 14:48:30 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  9 14:48:31 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  9 14:48:33 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  9 14:48:33 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  9 14:48:34 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  9 14:48:36 test02 check_reload_status: Updating all dyndns
    Aug  9 14:48:36 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  9 14:48:36 test02 check_reload_status: Restarting ipsec tunnels
    Aug  9 14:48:36 test02 check_reload_status: Reloading filter
    Aug  9 14:48:36 test02 check_reload_status: Restarting OpenVPN tunnels/interfaces
    Aug  9 14:48:38 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  9 14:48:38 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  9 14:48:41 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  9 14:48:44 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  9 14:48:44 test02 php: : Resyncing OpenVPN instances.
    Aug  9 14:48:45 test02 php: : DynDns: updatedns() starting
    Aug  9 14:48:45 test02 php: : running get_failover_interface for wan. found vr1
    Aug  9 14:48:45 test02 php: : There was an error trying to determine the public IP for interface - wan(vr1). Probably interface is not a WAN interface.
    Aug  9 14:48:46 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  9 14:48:46 test02 php: : Could not find IPv4 gateway for interface (wan).
    Aug  9 14:48:46 test02 kernel: arpresolve: can't allocate llinfo for 10.49.80.250
    Aug  9 14:48:47 test02 check_reload_status: Reloading filter
    Aug  9 14:48:54 test02 php: : Could not find IPv4 gateway for interface (wan).
    Aug  9 15:47:54 test02 dhclient[58767]: DHCPREQUEST on vr1 to 10.49.80.250 port 67
    Aug  9 15:47:54 test02 dhclient[58767]: send_packet: No route to host
    Aug  9 15:47:54 test02 dhclient[58767]: send_packet: No route to host
    Aug  9 15:47:55 test02 dhclient[58767]: DHCPREQUEST on vr1 to 10.49.80.250 port 67
    Aug  9 15:47:55 test02 dhclient[58767]: send_packet: No route to host
    Aug  9 15:47:55 test02 dhclient[58767]: send_packet: No route to host
    ...repeating about every minute
    
    

    At 14:47 something happened!
    Even if this is initiated by some transient issue on the switch connected to WAN, the software should be able to recover without user intervention. At the moment, the LAN side of the test system goes offline to the rest of the world. In a real remote access support situation that would be really annoying - no way to remotely get into the router to press release/renew. So it would be good to find the problem here, as it might save "random" problems in future for some production cases.
    I can't see a dhclient log file. Is there some way to see more about what is happening to dhclient?
    Is there other useful data I can dump from the system after this happens?




  • Has this issue fixed itself for you? I'm experiencing the same issue now that I moved to 2.1 dev. Going to update my snapshot as it's a week or so old.



  • I still get it on my test box every now and then (maybe about every 2 or 3 days). The WAN of the test box sits on my LAN and gets DHCP from the production pfSense that is talking to the real internet. All my production systems on the real internet have static IPs, so I can't say if there is any intermittent issue when getting DHCP from an ISP in some way.
    I am in an area with mains power that goes on and off all the time (10 times a day), we have UPS with big battery banks, but I think that sometimes the transitions back and forth from mains <-> inverter cause glitches for some of our switches. So the test box WAN physical switch might "disappear" for a moment and come back. I'll try and induce it by power cycling its local switch.


Locked