Navigation

    Netgate Discussion Forum
    • Register
    • Login
    • Search
    • Categories
    • Recent
    • Tags
    • Popular
    • Users
    • Search

    Connection does not recover if lost

    2.1 Snapshot Feedback and Problems - RETIRED
    6
    16
    3518
    Loading More Posts
    • Oldest to Newest
    • Newest to Oldest
    • Most Votes
    Reply
    • Reply as topic
    Log in to reply
    This topic has been deleted. Only users with topic management privileges can see it.
    • swinn
      swinn last edited by

      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
      1 Reply Last reply Reply Quote 0
      • W
        wallabybob last edited by

        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.
        1 Reply Last reply Reply Quote 0
        • D
          dhatz last edited by

          @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

          1 Reply Last reply Reply Quote 0
          • W
            wallabybob last edited by

            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.
            1 Reply Last reply Reply Quote 0
            • B
              bardelot last edited by

              @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.

              1 Reply Last reply Reply Quote 0
              • swinn
                swinn last edited by

                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.

                1 Reply Last reply Reply Quote 0
                • swinn
                  swinn last edited by

                  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
                  1 Reply Last reply Reply Quote 0
                  • B
                    bardelot last edited by

                    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.

                    1 Reply Last reply Reply Quote 0
                    • J
                      JWU42 last edited by

                      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.

                      1 Reply Last reply Reply Quote 0
                      • W
                        wallabybob last edited by

                        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.

                        1 Reply Last reply Reply Quote 0
                        • J
                          JWU42 last edited by

                          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";
}
                          1 Reply Last reply Reply Quote 0
                          • B
                            bardelot last edited by

                            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

                            1 Reply Last reply Reply Quote 0
                            • J
                              JWU42 last edited by

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

                              1 Reply Last reply Reply Quote 0
                              • P
                                phil.davis last edited by

                                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.

                                As the Greek philosopher Isosceles used to say, "There are 3 sides to every triangle."
                                If I helped you, then help someone else - buy someone a gift from the INF catalog http://secure.inf.org/gifts/usd/

                                1 Reply Last reply Reply Quote 0
                                • swinn
                                  swinn last edited by

                                  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
                                  1 Reply Last reply Reply Quote 0
                                  • J
                                    JWU42 last edited by

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

                                    1 Reply Last reply Reply Quote 0
                                    • First post
                                      Last post