Connection does not recover if lost

2.1 Snapshot Feedback and Problems - RETIRED
Log in to reply
  • swinn

    This has been happening for a few months but I finally remembered to save the log. If my connection drops from my ISP and comes back online, pfSense 2.1 will not recover from it until I renew DHCP from the Interfaces screen. The Interfaces screen will say DHCP is down before I renew.

    A little about my setup:

    • ISP is Charter running IPv4 (one IP address)
    • IPv6 is setup using 6rd
    • Packages installed includes Squid, Lightsquid, Snort and pfBlocker
    • OpenVPN is configured

    Here is the attached log before I renewed DHCP (note it is in reverse time order):

    Jan 17 14:40:42 miniupnpd[88244]: ioctl(s, SIOCGIFADDR, ...): Can't assign requested address 
Jan 17 14:40:42 miniupnpd[88244]: ioctl(s, SIOCGIFADDR, ...): Can't assign requested address 
Jan 17 14:40:26 kernel: arpresolve: can't allocate llinfo for 75.131.112.1 
Jan 17 14:39:22 kernel: arpresolve: can't allocate llinfo for 75.131.112.1 
Jan 17 14:38:18 kernel: arpresolve: can't allocate llinfo for 75.131.112.1 
Jan 17 14:37:22 kernel: pid 76094 (filterdns), uid 0: exited on signal 11 (core dumped) 
Jan 17 14:37:14 kernel: arpresolve: can't allocate llinfo for 75.131.112.1 
Jan 17 14:36:10 kernel: arpresolve: can't allocate llinfo for 75.131.112.1 
Jan 17 14:35:40 kernel: arpresolve: can't allocate llinfo for 75.131.112.1 
Jan 17 14:35:26 kernel: arpresolve: can't allocate llinfo for 75.131.112.1 
Jan 17 14:35:06 kernel: arpresolve: can't allocate llinfo for 75.131.112.1 
Jan 17 14:34:43 miniupnpd[88244]: SendNATPMPPublicAddressChangeNotification: sendto(s_udp=14): No route to host 
Jan 17 14:34:42 kernel: em0: link state changed to UP 
Jan 17 14:34:42 php: : Created 6rd interface stf0 2602:100::/32 
Jan 17 14:34:42 php: : The command '/sbin/ifconfig stf0 create' returned exit code '1', the output was 'ifconfig: create: bad value' 
Jan 17 14:34:42 php: : The command '/sbin/dhclient -c /var/etc/dhclient_wan.conf em0 > /tmp/em0_output > /tmp/em0_error_output' returned exit code '15', the output was '' 
Jan 17 14:34:42 dhclient[67737]: exiting. 
Jan 17 14:34:42 dhclient[67737]: connection closed 
Jan 17 14:34:42 php: : Calling interface down for interface wan, destroy is false 
Jan 17 14:34:42 php: : DEVD Ethernet detached event for wan 
Jan 17 14:34:42 dhclient[67469]: DHCPREQUEST on em0 to 255.255.255.255 port 67 
Jan 17 14:34:40 dhclient[67469]: DHCPREQUEST on em0 to 255.255.255.255 port 67 
Jan 17 14:34:39 kernel: em0: link state changed to DOWN 
Jan 17 14:34:39 check_reload_status: Linkup starting em0 
Jan 17 14:34:39 dhclient[67469]: DHCPREQUEST on em0 to 255.255.255.255 port 67 
Jan 17 14:34:39 dhclient: Comparing Routers: Old: New: 
Jan 17 14:34:39 dhclient: Comparing IPs: Old: New: 
Jan 17 14:34:39 dhclient: Starting delete_old_states() 
Jan 17 14:34:39 miniupnpd[88244]: SendNATPMPPublicAddressChangeNotification: sendto(s_udp=14): No route to host 
Jan 17 14:34:39 dhclient: PREINIT 
Jan 17 14:34:38 php: : Calling interface down for interface wan, destroy is false 
Jan 17 14:34:38 php: : Deny router advertisements for interface wan 
Jan 17 14:34:38 php: : HOTPLUG: Configuring interface wan 
Jan 17 14:34:38 php: : DEVD Ethernet attached event for wan 
Jan 17 14:34:36 kernel: em0: link state changed to UP 
Jan 17 14:34:36 check_reload_status: Linkup starting em0 
Jan 17 14:34:33 kernel: arpresolve: can't allocate llinfo for 75.131.112.1 
Jan 17 14:34:22 dhclient[53195]: exiting. 
Jan 17 14:34:22 dhclient[53195]: connection closed 
Jan 17 14:34:22 php: : Calling interface down for interface wan, destroy is false 
Jan 17 14:34:22 php: : DEVD Ethernet detached event for wan 
Jan 17 14:34:20 kernel: em0: link state changed to DOWN 
Jan 17 14:34:20 check_reload_status: Linkup starting em0
    0
  • W

    At least part of your problem is```

    Jan 17 14:34:42 php: : The command '/sbin/dhclient -c /var/etc/dhclient_wan.conf em0 > /tmp/em0_output > /tmp/em0_error_output' returned exit code '15', the output was ''

    
Please post the contents of /tmp/em0*

There is probably something wrong with the replicated redirection of stdout.

(dhclient is the program that sends DHCP requests and acts on the response.)

What pfSense build are you using? If it is more that a couple of months old it would be worth updating the firmware to see if the problem is still there.
    0
  • D

    @wallabybob:

    At least part of your problem is```

    Jan 17 14:34:42 php: : The command '/sbin/dhclient -c /var/etc/dhclient_wan.conf em0 > /tmp/em0_output > /tmp/em0_error_output' returned exit code '15', the output was ''

    Hmm, this seems to be an error in 2.1-BETA latest snap in /etc/inc/interfaces.inc line 3475

    /sbin/dhclient -c /var/etc/dhclient_wan.conf em0 > /tmp/em0_output 2> /tmp/em0_error_output

    0
  • W

    I'm running

    2.0.1-RELEASE (i386)
    built on Mon Dec 12 17:53:52 EST 2011
    FreeBSD 8.1-RELEASE-p4

    and my /etc/inc/interfaces.inc includes double redirections of stdout on the dhclient command:```
            /* fire up dhclient */
            mwexec("/sbin/dhclient -c {$g['varetc_path']}/dhclient_{$interface}.conf {$wanif} > {$g['tmp_path']}/{$wanif}_output > $g['tmp_path']}/{$wanif}_error_output");

    
To clarify, the problem I was referring to was that dhclient apparently exits "immediately" rather than sending DHCP request and waiting for response.
    0
  • B

    @wallabybob:

    To clarify, the problem I was referring to was that dhclient apparently exits "immediately" rather than sending DHCP request and waiting for response.

    The error output is not redirected properly the second > should be 2>, otherwise you could check the /tmp/{$wanif}_error_output file for an error message.

    0
  • swinn

    My current version is:
    2.1-BETA1  (i386)
    built on Mon Jan 7 16:18:13 EST 2013
    FreeBSD 8.3-RELEASE-p5

    This has been happening for a couple of months. I update builds about once a week or so.

    After looking at the em0 files, they have all been overwritten since the time the connection was lost. Next time it happens, I'll save them so I can post their contents.

    0
  • swinn

    Ok, it happened again this morning. Here are the contents of the em0 files and the portion of the log:

    em0_defaultgw:
75.131.112.1

em0_defaultgwv6:
2602:100:4472:a501::

em0_error_output:
dhclient: PREINIT
dhclient: Starting delete_old_states()
OLD_IP: not found
dhclient: Comparing IPs: Old:  New: 
OLD_ROUTER: not found
dhclient: Comparing Routers: Old:  New: 
DHCPREQUEST on em0 to 255.255.255.255 port 67
DHCPREQUEST on em0 to 255.255.255.255 port 67
DHCPREQUEST on em0 to 255.255.255.255 port 67

em0_output:

em0_routerv6:
2602:100:4472:a501::

system log:
Jan 18 09:32:14 kernel: arpresolve: can't allocate llinfo for 75.131.112.1 
Jan 18 09:32:13 miniupnpd[88244]: ioctl(s, SIOCGIFADDR, ...): Can't assign requested address 
Jan 18 09:32:13 miniupnpd[88244]: ioctl(s, SIOCGIFADDR, ...): Can't assign requested address 
Jan 18 09:32:13 miniupnpd[88244]: SendNATPMPPublicAddressChangeNotification: sendto(s_udp=14): No route to host 
Jan 18 09:32:13 kernel: arpresolve: can't allocate llinfo for 75.131.112.1 
Jan 18 09:32:13 kernel: em0: link state changed to UP 
Jan 18 09:32:12 php: : Created 6rd interface stf0 2602:100::/32 
Jan 18 09:32:12 php: : The command '/sbin/ifconfig stf0 create' returned exit code '1', the output was 'ifconfig: create: bad value' 
Jan 18 09:32:12 php: : The command '/sbin/dhclient -c /var/etc/dhclient_wan.conf em0 > /tmp/em0_output > /tmp/em0_error_output' returned exit code '15', the output was '' 
Jan 18 09:32:12 dhclient[84176]: exiting. 
Jan 18 09:32:12 dhclient[84176]: connection closed 
Jan 18 09:32:12 php: : Calling interface down for interface wan, destroy is false 
Jan 18 09:32:12 php: : DEVD Ethernet detached event for wan 
Jan 18 09:32:12 kernel: arpresolve: can't allocate llinfo for 75.131.112.1 
Jan 18 09:32:12 dhclient[84136]: DHCPREQUEST on em0 to 255.255.255.255 port 67 
Jan 18 09:32:11 kernel: arpresolve: can't allocate llinfo for 75.131.112.1 
Jan 18 09:32:11 kernel: arpresolve: can't allocate llinfo for 75.131.112.1 
Jan 18 09:32:10 kernel: em0: link state changed to DOWN 
Jan 18 09:32:10 kernel: arpresolve: can't allocate llinfo for 75.131.112.1 
Jan 18 09:32:10 check_reload_status: Linkup starting em0 
Jan 18 09:32:10 dhclient[84136]: DHCPREQUEST on em0 to 255.255.255.255 port 67 
Jan 18 09:32:09 dhclient[84136]: DHCPREQUEST on em0 to 255.255.255.255 port 67 
Jan 18 09:32:09 dhclient: Comparing Routers: Old: New: 
Jan 18 09:32:09 dhclient: Comparing IPs: Old: New: 
Jan 18 09:32:09 dhclient: Starting delete_old_states() 
Jan 18 09:32:09 miniupnpd[88244]: SendNATPMPPublicAddressChangeNotification: sendto(s_udp=14): No route to host 
Jan 18 09:32:09 dhclient: PREINIT 
Jan 18 09:32:08 php: : Calling interface down for interface wan, destroy is false 
Jan 18 09:32:08 php: : Deny router advertisements for interface wan 
Jan 18 09:32:08 php: : HOTPLUG: Configuring interface wan 
Jan 18 09:32:08 php: : DEVD Ethernet attached event for wan 
Jan 18 09:32:08 kernel: arpresolve: can't allocate llinfo for 75.131.112.1 
Jan 18 09:32:06 kernel: arpresolve: can't allocate llinfo for 75.131.112.1 
Jan 18 09:32:06 kernel: arpresolve: can't allocate llinfo for 75.131.112.1 
Jan 18 09:32:06 kernel: em0: link state changed to UP 
Jan 18 09:32:06 check_reload_status: Linkup starting em0 
Jan 18 09:32:05 kernel: arpresolve: can't allocate llinfo for 75.131.112.1 
Jan 18 09:32:05 kernel: arpresolve: can't allocate llinfo for 75.131.112.1 
Jan 18 09:32:03 miniupnpd[88244]: Failed to get ip address for interface em0 
Jan 18 09:32:03 miniupnpd[88244]: ioctl(s, SIOCGIFADDR, ...): Can't assign requested address 
Jan 18 09:31:59 kernel: arpresolve: can't allocate llinfo for 75.131.112.1 
Jan 18 09:31:59 miniupnpd[88244]: Failed to get ip address for interface em0 
Jan 18 09:31:59 miniupnpd[88244]: ioctl(s, SIOCGIFADDR, ...): Can't assign requested address 
Jan 18 09:31:59 kernel: arpresolve: can't allocate llinfo for 75.131.112.1 
Jan 18 09:31:59 kernel: arpresolve: can't allocate llinfo for 75.131.112.1 
Jan 18 09:31:58 kernel: arpresolve: can't allocate llinfo for 75.131.112.1
    0
  • B

    The connection seems to drop multiple times very quickly while pfSense is trying to reconfigure the interface. There might be interference as it takes a few seconds to reconfigure. My best guess would be a workaround using a cron job that checks every few minutes if DHCP is down and restarts it or even reconfigures the interface from scratch.

    0
  • J

    Seeing this even in 2.0.2 - twice for me since updating from 2.0.1  :(

    Jan 18 09:53:47	php: : The command '/sbin/dhclient -c /var/etc/dhclient_wan.conf em3 > /tmp/em3_output > /tmp/em3_error_output' returned exit code '15', the output was ''

    Much like the OP, I had to re-configure the interface on the box to get DHCP working and therefore an active connection.

    0
  • W

    Unfortunately the dhclient man page doesn't give an explanation of the various exit codes used so I suppose someone should fix the command so stderr gets captured into a file and troll through the source code to see the significance of exit code 15.

    0
  • J

    Pardon my n00bishness…

    Does it matter that the .conf it is trying to load shows a retry of 1.  Maybe that simply means "true" and it will keep retrying?

    interface "em3" {
timeout 60;
retry 1;
select-timeout 0;
initial-interval 1;

	script "/sbin/dhclient-script";
}
    0
  • B

    It's the minimum time before sending another DHCP request when no server has answered.

    retry time;
        The retry statement determines the time that must pass after the
        client has determined that there is no DHCP server present before
        it tries again to contact a DHCP server.  By default, this is
        five minutes.

    The dhclient dies when the interface goes down but the interface (and dhclient) is reconfigured when a linkup is detected.

    [1] http://www.freebsd.org/cgi/man.cgi?query=dhclient.conf&sektion=5

    0
  • J

    Have updated to 2.1 and maybe my issue goes away  :D

    0
  • P

    Once the "kernel: arpresolve: can't allocate llinfo" message starts happening, it seems to always require the DHCP release/renew sequence (whatever the button on status interfaces does) in order to get it back. In my case, my test system WAN is connected to a little switch on my desk that is 220V, but I am in a location that has really bad power, often dipping to less than 150V. The power supply is not a 110-220V one! When the switch starts to go "funny" on low voltage, the pfSense WAN is coming and going quickly. That induces the above effects, the WAN comes back and is gone again while pfSense software is still reacting to it having come back. Ideally the software would handle all sorts of nasty things happening half-way through processing, but it doesn't. So, a dodgy WAN connection that comes-and-goes can induce this issue.

    0
  • swinn

    I reconfigured the router last night. Updated build, installed packages from scratch and reconfigured. This never occurred with 2.0.1 - it would always recover just fine. Someone else reported they saw it happen with 2.0.2 but I haven't tried that version.

    From this morning:

    Jan 23 06:41:14 miniupnpd[92366]: upnp_event_send: send(): Broken pipe 
Jan 23 06:41:14 miniupnpd[92366]: ioctl(s, SIOCGIFADDR, ...): Can't assign requested address 
Jan 23 06:41:14 miniupnpd[92366]: ioctl(s, SIOCGIFADDR, ...): Can't assign requested address 
Jan 23 06:41:09 kernel: arpresolve: can't allocate llinfo for 75.131.112.1 
Jan 23 06:40:21 kernel: arpresolve: can't allocate llinfo for 75.131.112.1 
Jan 23 06:40:20 miniupnpd[92366]: SendNATPMPPublicAddressChangeNotification: sendto(s_udp=14): No route to host 
Jan 23 06:40:19 kernel: em0: link state changed to UP 
Jan 23 06:40:19 php: : Created 6rd interface stf0 2602:100::/32 
Jan 23 06:40:19 php: : The command '/sbin/ifconfig stf0 create' returned exit code '1', the output was 'ifconfig: create: bad value' 
Jan 23 06:40:19 php: : The command '/sbin/dhclient -c /var/etc/dhclient_wan.conf em0 > /tmp/em0_output 2> /tmp/em0_error_output' returned exit code '15', the output was '' 
Jan 23 06:40:19 dhclient[86506]: exiting. 
Jan 23 06:40:19 dhclient[86506]: connection closed 
Jan 23 06:40:18 php: : Calling interface down for interface wan, destroy is false 
Jan 23 06:40:18 php: : DEVD Ethernet detached event for wan 
Jan 23 06:40:17 dhclient[86298]: DHCPREQUEST on em0 to 255.255.255.255 port 67 
Jan 23 06:40:16 kernel: em0: link state changed to DOWN 
Jan 23 06:40:16 check_reload_status: Linkup starting em0 
Jan 23 06:40:15 dhclient[86298]: DHCPREQUEST on em0 to 255.255.255.255 port 67 
Jan 23 06:40:15 dhclient: Comparing Routers: Old: New: 
Jan 23 06:40:15 dhclient: Comparing IPs: Old: New: 
Jan 23 06:40:15 dhclient: Starting delete_old_states() 
Jan 23 06:40:15 miniupnpd[92366]: SendNATPMPPublicAddressChangeNotification: sendto(s_udp=14): No route to host 
Jan 23 06:40:15 dhclient: PREINIT 
Jan 23 06:40:14 php: : Calling interface down for interface wan, destroy is false 
Jan 23 06:40:14 php: : Deny router advertisements for interface wan 
Jan 23 06:40:14 php: : HOTPLUG: Configuring interface wan 
Jan 23 06:40:14 php: : DEVD Ethernet attached event for wan 
Jan 23 06:40:12 kernel: em0: link state changed to UP 
Jan 23 06:40:12 check_reload_status: Linkup starting em0
    0
  • J

    Not encouraging to see this is still around in 2.1  ::)

    0

Products

Services

Support

News

Resources

Company

Our Mission

We provide leading-edge network security at a fair price - regardless of organizational size or network sophistication. We believe that an open-source security model offers disruptive pricing along with the agility required to quickly address emerging threats.

Subscribe to our Newsletter

Product information, software announcements, and special offers. See our newsletter archive to sign up for future newsletters and to read past announcements.

© 2020 Rubicon Communications, LLC | Privacy Policy