WAN DHCP issues Telenet, arpresolve: can't allocate llinfo



  • Hi,

    It's me again with an update on the issue I reported a while ago: http://forum.pfsense.org/index.php/topic,42473

    I'm totally stuck on this for a long time now, if I can't figure it out, I will try replacing the boxes and see if that helps. (but I doubt that)

    In the night (2-3 times/week) the boxes lose their internet connection, I configured syslog to log to a linux syslog server on the LAN so we could at least catch the logs after the on-site person power cycles the firewall. (the boxes are remote)

    The loss of connection started around 5:10am and lasted until the reboot at 09.00am. The last dhcp RENEW before 05.10 was at 04.52 and went "normal".

    Is there anything else I need to check or that I can do to troubleshoot?

    Tech specs:
    2.0.1-RELEASE (i386) - built on Mon Dec 12 19:00:03 EST 2011 - FreeBSD 8.1-RELEASE-p6
    The internet connection is cable and IPs are issued by DHCP.
    WAN (wan)                 -> vr1        -> 81.82.xxx.xxx (DHCP)
    LAN (lan)                 -> vr0        -> 192.168.10.254
    OPT1 (opt1)               -> vr2        -> NONE

    I attached some logs, if you need more, let me know, I can grab them easily.

    kern:

    kern
    Jul 13 05:10:35 192.168.10.254 kernel: vr1: link state changed to DOWN
    Jul 13 05:10:55 192.168.10.254 kernel: vr1: link state changed to UP
    Jul 13 05:11:04 192.168.10.254 kernel: vr1: link state changed to DOWN
    Jul 13 05:11:06 192.168.10.254 kernel: vr1: link state changed to UP
    Jul 13 05:52:29 192.168.10.254 kernel: arpresolve: can't allocate llinfo for 81.82.192.1
    Jul 13 05:52:31 192.168.10.254 kernel: arpresolve: can't allocate llinfo for 81.82.192.1
    Jul 13 05:52:36 192.168.10.254 kernel: arpresolve: can't allocate llinfo for 81.82.192.1
    Jul 13 05:52:44 192.168.10.254 kernel: arpresolve: can't allocate llinfo for 81.82.192.1
    Jul 13 05:52:52 192.168.10.254 kernel: arpresolve: can't allocate llinfo for 81.82.192.1
    Jul 13 05:53:05 192.168.10.254 kernel: arpresolve: can't allocate llinfo for 81.82.192.1
    Jul 13 05:53:17 192.168.10.254 kernel: arpresolve: can't allocate llinfo for 81.82.192.1
    Jul 13 05:53:46 192.168.10.254 kernel: arprequest: cannot find matching address
    Jul 13 05:53:46 192.168.10.254 kernel: arprequest: cannot find matching address
    ...
    Jul 13 05:56:35 192.168.10.254 kernel: arprequest: cannot find matching address
    Jul 13 05:56:35 192.168.10.254 kernel: arprequest: cannot find matching address
    Jul 13 05:56:37 192.168.10.254 kernel: arpresolve: can't allocate llinfo for 81.82.192.1
    Jul 13 05:56:38 192.168.10.254 kernel: arprequest: cannot find matching address
    Jul 13 05:56:38 192.168.10.254 kernel: arprequest: cannot find matching address
    Jul 13 05:56:40 192.168.10.254 kernel: arprequest: cannot find matching address
    ... Repeats until reboot
    
    
    Jul 13 04:52:29 192.168.10.254 dhclient: RENEW
    Jul 13 04:52:29 192.168.10.254 dhclient: Creating resolv.conf
    Jul 13 05:10:10 192.168.10.254 apinger: ALARM: WAN(81.82.192.1)  *** down ***
    Jul 13 05:10:20 192.168.10.254 check_reload_status: Reloading filter
    Jul 13 05:10:35 192.168.10.254 check_reload_status: Linkup starting vr1
    Jul 13 05:10:41 192.168.10.254 php: : DEVD Ethernet detached event for wan
    Jul 13 05:10:55 192.168.10.254 check_reload_status: Linkup starting vr1
    Jul 13 05:11:01 192.168.10.254 php: : DEVD Ethernet attached event for wan
    Jul 13 05:11:01 192.168.10.254 php: : HOTPLUG: Configuring interface wan
    Jul 13 05:11:01 192.168.10.254 dhclient: PREINIT
    Jul 13 05:11:04 192.168.10.254 check_reload_status: Linkup starting vr1
    Jul 13 05:11:06 192.168.10.254 check_reload_status: Linkup starting vr1
    Jul 13 05:11:09 192.168.10.254 php: : DEVD Ethernet detached event for wan
    Jul 13 05:11:10 192.168.10.254 php: : The command '/sbin/dhclient -c /var/etc/dhclient_wan.conf vr1 > /tmp/vr1_output > /tmp/vr1_error_output' returned exit code '15', the output was ''
    Jul 13 05:11:12 192.168.10.254 php: : DEVD Ethernet attached event for wan
    Jul 13 05:11:12 192.168.10.254 php: : HOTPLUG: Configuring interface wan
    Jul 13 05:11:12 192.168.10.254 dhclient: PREINIT
    Jul 13 05:12:24 192.168.10.254 dhclient: TIMEOUT
    Jul 13 05:12:24 192.168.10.254 dhclient: Starting add_new_address()
    Jul 13 05:12:24 192.168.10.254 dhclient: ifconfig vr1 inet 81.82.xxx.xxxnetmask 255.255.192.0 broadcast 255.255.255.255
    Jul 13 05:12:24 192.168.10.254 dhclient: New IP Address (vr1): 81.82.xxx.xxx
    Jul 13 05:12:24 192.168.10.254 dhclient: New Subnet Mask (vr1): 255.255.192.0
    Jul 13 05:12:24 192.168.10.254 dhclient: New Broadcast Address (vr1): 255.255.255.255
    Jul 13 05:12:24 192.168.10.254 dhclient: New Routers (vr1): 81.82.192.1
    Jul 13 05:12:25 192.168.10.254 dhclient: New Routers (vr1): 81.82.192.1
    Jul 13 05:12:36 192.168.10.254 dhclient: Deleting old routes
    Jul 13 05:53:45 192.168.10.254 dhclient: RENEW
    Jul 13 05:53:45 192.168.10.254 dhclient: Creating resolv.conf
    Jul 13 06:55:03 192.168.10.254 dhclient: RENEW
    Jul 13 06:55:03 192.168.10.254 dhclient: Creating resolv.conf
    Jul 13 07:56:06 192.168.10.254 dhclient: RENEW
    Jul 13 07:56:07 192.168.10.254 dhclient: Creating resolv.conf
    Jul 13 08:57:07 192.168.10.254 dhclient: RENEW
    Jul 13 08:57:07 192.168.10.254 dhclient: Creating resolv.conf
    Jul 13 09:00:39 192.168.10.254 apinger: Starting Alarm Pinger, apinger(36434)
    Jul 13 09:00:43 192.168.10.254 php: : ROUTING: setting default route to 81.82.192.1
    Jul 13 09:00:45 192.168.10.254 check_reload_status: Updating all dyndns
    Jul 13 09:00:49 192.168.10.254 php: : OpenNTPD is starting up.
    Jul 13 09:00:49 192.168.10.254 php: : rc.newwanip: Informational is starting vr1.
    Jul 13 09:00:49 192.168.10.254 php: : rc.newwanip: on (IP address: 81.82.xxx.xxx) (interface: wan) (real interface: vr1).
    Jul 13 09:00:50 192.168.10.254 php: : ROUTING: setting default route to 81.82.192.1
    Jul 13 09:00:50 192.168.10.254 apinger: Exiting on signal 15.
    Jul 13 09:00:51 192.168.10.254 check_reload_status: rc.newwanip starting ovpnc1
    Jul 13 09:00:51 192.168.10.254 check_reload_status: Reloading filter
    Jul 13 09:00:51 192.168.10.254 apinger: Starting Alarm Pinger, apinger(5223)
    Jul 13 09:00:51 192.168.10.254 check_reload_status: Restarting ipsec tunnels
    Jul 13 09:00:56 192.168.10.254 php: : Resyncing OpenVPN instances for interface WAN.
    Jul 13 09:00:56 192.168.10.254 php: : Creating rrd update script
    
    

    The hardware is from applianceshop:
    http://www.applianceshop.eu/index.php/firewalls/opnsense/opnsense-desktop-and-wallmountable/opnsense-pfsense-appliance.html

    Thanks in advance for any reply

    Kristof



  • The "arpresolve: can't allocate llinfo" generally means it's trying to ARP something that isn't on a local subnet. The "New Broadcast Address (vr1): 255.255.255.255" is odd, as well as the fact the NIC loses link twice, and once it regains it that's part of the lease it gets. Suspect that's somehow related (getting a bunk lease?), but not sure how exactly from that.



  • @cmb:

    The "arpresolve: can't allocate llinfo" generally means it's trying to ARP something that isn't on a local subnet. The "New Broadcast Address (vr1): 255.255.255.255" is odd, as well as the fact the NIC loses link twice, and once it regains it that's part of the lease it gets. Suspect that's somehow related (getting a bunk lease?), but not sure how exactly from that.

    I'm not sure if the "can't allocate llinfo" has anything to do with it but it seems strange to me that the lease gets renewed at 5.12 but the internet connection is not working.

    It seems indeed we get an "invalid lease" that seems to be ok but does not work correctly. (= can't allocate llinfo for 81.82.192.1)

    Any ideas on how to workaround this? Or "detecting" that this is happening and forcing a release/renew or something alike?

    regards,
    Kristof.


  • Rebel Alliance Developer Netgate

    It could be a situation like I get here:

    • Cable modem loses sync, modem hands out 192.168.x.x address to WAN
    • WAN gets some states routing traffic via the 192.168.x.x. gateway
    • Cable modem regains sync, modem passes on public IP lease
    • WAN states start going to the right gateway

    If some states are still around on the bad/stale gateway, I get the arpresolve error. If I reset the states going via that gateway (pfctl -b x.x.x.x) or reset the whole state table, it clears up.

    This is a bit better on 2.1 these days but it's been a while since I tested it out.



  • I don't really think it's something with a 192.168.x.x address as I don't find anything (at all) about that in the logfiles.

    But I'm willing to try a somewhat stable 2.1 snapshot, can you point me to where I can find them?


  • Rebel Alliance Developer Netgate


Log in to reply