pfSense Gold Subscription

Author Topic: I have to manually reset states after WAN down to allow Asterisk to re-register.  (Read 7471 times)

0 Members and 1 Guest are viewing this topic.

Offline davros123

  • Jr. Member
  • **
  • Posts: 62
  • Karma: +3/-0
    • View Profile
Hello,
    I am experiencing an issue with Asterisk not reconnecting unless I manually delete the states.

Un-ticking this option does not provide a resolution...even though it should remove all active states.



Happy to try anything and provide whatever debug info. is needed.  Thanks for looking !

Summary:

Everything works perfectly, until I pull out and plugin the phone line to the dsl modem...then Asterisk can no longer register with my provider.

I did not have this issue prior to using pfsense.


I am testing by removing the phone line from the dsl modem (which is in bridged mode connected to the wan port with pfsense doing PPPoE).

Asterisk 1.8.20.1 (running as Elastix 2.4).
pfsense 2.1-RELEASE (i386)  built on Wed Sep 11 18:16:22 EDT 2013 FreeBSD 8.3-RELEASE-p11


I have set up a static rule using "Manual Outbound NAT rule generation (AON - Advanced Outbound NAT)"

I also have port forwarded 10000-20000.

This is what i see in the system log...
Code: [Select]
Dec 11 13:10:58 apinger: alarm canceled: WAN_PPPOE(202.138.4.81) *** WAN_PPPOEdown ***
Dec 11 13:12:15 apinger: ALARM: WAN_PPPOE(202.138.4.81) *** WAN_PPPOEdown ***
Dec 11 13:17:17 apinger: SIGHUP received, reloading configuration.
Dec 11 13:17:17 apinger: alarm canceled (config reload): WAN_PPPOE(202.138.4.81) *** WAN_PPPOEdown ***
Code: [Select]
Dec 11 13:17:17 php: rc.newwanip: ROUTING: setting default route to 202.138.4.81
Dec 11 13:17:17 php: rc.newwanip: DynDns: updatedns() starting
...
Dec 11 13:17:32 php: rc.newwanip: pfSense package system has detected an ip change 211.27.74.200 -> 116.240.129.229 ... Restarting packages.
Dec 11 13:17:32 check_reload_status: Starting packages
Dec 11 13:17:32 check_reload_status: Reloading filter
Dec 11 13:17:34 php: rc.start_packages: Restarting/Starting all packages.
Dec 11 13:17:35 php: rc.filter_configure_sync: Not installing NAT reflection rules for a port range > 500
Dec 11 13:17:37 php: rc.start_packages: The command '/usr/local/etc/rc.d/bandwidthd.sh stop' returned exit code '1', the output was 'No matching processes were found'
Dec 11 13:17:40 bandwidthd: Monitoring subnet 192.168.0.0 with netmask 192.168.0.0
Dec 11 13:17:42 bandwidthd: Monitoring subnet 192.168.0.0 with netmask 192.168.0.0
Dec 11 13:17:42 bandwidthd: Opening em0
Dec 11 13:17:42 bandwidthd: Opening em0
Dec 11 13:17:42 bandwidthd: Opening em0
Dec 11 13:17:42 bandwidthd: Opening em0
Dec 11 13:17:42 bandwidthd: Packet Encoding: Ethernet
Dec 11 13:17:42 bandwidthd: Packet Encoding: Ethernet
Dec 11 13:17:42 bandwidthd: Packet Encoding: Ethernet
Dec 11 13:17:42 bandwidthd: Packet Encoding: Ethernet
Dec 11 13:17:44 nrpe[70969]: Caught SIGTERM - shutting down...
Dec 11 13:17:44 nrpe[70969]: Cannot remove pidfile '/var/run/nrpe2.pid' - check your privileges.
Dec 11 13:17:44 nrpe[70969]: Daemon shutdown
Dec 11 13:17:44 nrpe[94420]: Starting up daemon
Dec 11 13:17:44 nrpe[94420]: Listening for connections on port 5666
Dec 11 13:17:44 nrpe[94420]: Allowing connections from: 127.0.0.1
Dec 11 13:17:46 php: rc.start_packages: No pfBlocker action during boot process.
Dec 11 13:17:46 php: rc.start_packages: No pfBlocker action during boot process.
Dec 11 13:17:46 php: rc.start_packages: No pfBlocker action during boot process.
Dec 11 13:17:46 php: rc.start_packages: No pfBlocker action during boot process.
Dec 11 13:17:48 php: rc.start_packages: Reloading Squid for configuration sync
Dec 11 13:17:48 check_reload_status: Reloading filter
Dec 11 13:17:50 php: rc.start_packages: Reloading Squid for configuration sync
Dec 11 13:17:50 php: rc.start_packages: Reloading Squid for configuration sync
Dec 11 13:17:50 php: rc.start_packages: Not calling package sync code for dependency squid of squid because some include files are missing.
Dec 11 13:17:50 php: rc.start_packages: Reloading Squid for configuration sync
Dec 11 13:17:50 php: rc.start_packages: Reloading Squid for configuration sync
Dec 11 13:17:50 php: rc.start_packages: Reloading Squid for configuration sync
Dec 11 13:17:50 php: rc.start_packages: Reloading Squid for configuration sync
Dec 11 13:17:51 php: rc.filter_configure_sync: Not installing NAT reflection rules for a port range > 500
Dec 11 13:17:54 squid[99913]: Squid Parent: child process 272 exited with status 0
Dec 11 13:17:55 php: rc.start_packages: The command '/usr/local/etc/rc.d/squid.sh stop' returned exit code '1', the output was ''
Dec 11 13:17:57 squid[43512]: Squid Parent: child process 43730 started
Dec 11 13:17:59 php: rc.start_packages: The command '/usr/local/etc/rc.d/darkstat.sh stop' returned exit code '1', the output was 'No matching processes were found'






Is there anything else I should be doing?

It all works fine, except for the re-registering...(which works immediately that I delete the states).

As a temporary workaround, I have modified /usr/local/sbin/ppp-linkup as suggested in this post

It calls the following script (/usr/local/sbin/voip-wan-wipe-states) to clear the states for the asterisk session once the Wan (PPPoE) is back up.
Code: [Select]
#!/bin/sh
sleep 30
pfctl -k 192.168.0.5

Surely this should not be needed as this is what unticking the box in the settings should do...no?
« Last Edit: December 13, 2013, 05:06:10 am by davros123 »

Offline stephenw10

  • Administrator
  • Hero Member
  • *****
  • Posts: 11959
  • Karma: +469/-15
    • View Profile
Hmm this should have been fixed:
https://redmine.pfsense.org/issues/2887

Do you have those revisions in rc.kill_states?

Steve

Offline davros123

  • Jr. Member
  • **
  • Posts: 62
  • Karma: +3/-0
    • View Profile
Hi Thanks for the reply...I read it was fixed too so this is quite puzzling.

Below is the code in /etc/rc.kill_states...
Perhaps I need to put some logging code in there to see why it appears not to be removing the states.

Quote
cat  /etc/rc.*kill_states
#!/usr/local/bin/php -f
<?php
/*
        rc.newwanip
        Copyright (C) 2013 Renato Botelho (garga@pfsense.org)
        part of pfSense (http://www.pfsense.com)

        Redistribution and use in source and binary forms, with or without
        modification, are permitted provided that the following conditions are m                                               et:

        1. Redistributions of source code must retain the above copyright notice                                               ,
        this list of conditions and the following disclaimer.

        2. Redistributions in binary form must reproduce the above copyright
        notice, this list of conditions and the following disclaimer in the
        documentation and/or other materials provided with the distribution.

        THIS SOFTWARE IS PROVIDED ``AS IS'' AND ANY EXPRESS OR IMPLIED WARRANTIE                                               S,
        INCLUDING, BUT NOT LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY
        AND FITNESS FOR A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL T                                               HE
        AUTHOR BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLAR                                               Y,
        OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF
        SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS
        INTERRUPTION) HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN
        CONTRACT, STRICT LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE)
        ARISING IN ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF T                                               HE
        POSSIBILITY OF SUCH DAMAGE.
*/

/* parse the configuration and include all functions used below */
require_once("globals.inc");
require_once("config.inc");
require_once("interfaces.inc");
require_once("util.inc");

// Do not process while booting
if($g['booting'])
        exit;

/* Interface address to cleanup states */
$interface = str_replace("\n", "", $argv[1]);

/* IP address to cleanup states */
$local_ip = str_replace("\n", "", $argv[2]);

if (empty($interface) || !does_interface_exist($interface)) {
        log_error("rc.kill_states: Invalid interface '{$interface}'");
        exit;
}

if (!empty($local_ip)) {
        list($local_ip, $subnet_bits) = explode("/", $local_ip);

        if (empty($subnet_bits))
                $subnet_bits = "32";

        if (!is_ipaddr($local_ip)) {
                log_error("rc.kill_states: Invalid IP address '{$local_ip}'");
                exit;
        }
}

if (!isset($config['system']['kill_states'])) {
        if (!empty($local_ip)) {
                log_error("rc.kill_states: Removing states for IP {$local_ip}/{$                                               subnet_bits}");
                $nat_states = exec_command("/sbin/pfctl -i {$interface} -ss | "                                                .
                        "/usr/bin/egrep '\-> +{$local_ip}:[0-9]+ +\->'");

                $cleared_states = array();
                foreach(explode("\n", $nat_states) as $nat_state) {
                        if (preg_match_all('/([\d\.]+):[\d]+[\s->]+/i', $nat_sta                                               te, $matches, PREG_SET_ORDER) != 3)
                                continue;

                        $src = $matches[0][1];
                        $dst = $matches[2][1];

                        if (empty($src) || empty($dst) || in_array("{$src},{$dst                                               }", $cleared_states))
                                continue;

                        $cleared_states[] = "{$src},{$dst}";
                        mwexec("/sbin/pfctl -k {$src} -k {$dst}", true);
                }

                mwexec("/sbin/pfctl -k 0.0.0.0/0 -k {$local_ip}/{$subnet_bits}",                                                true);
                mwexec("/sbin/pfctl -k {$local_ip}/{$subnet_bits}", true);
                mwexec("/sbin/pfctl -K {$local_ip}/{$subnet_bits}", true);
        }
        log_error("rc.kill_states: Removing states for interface {$interface}");
        mwexec("/sbin/pfctl -i {$interface} -Fs", true);

Offline charliem

  • Sr. Member
  • ****
  • Posts: 565
  • Karma: +43/-1
    • View Profile
Just a 'me too' here, though I'm using a cablemodem rather than dsl, and a linksys PAP2T adapter rather than asterisk.  My symptoms are exactly the same: when my cable modem occasionally reboots itself, everything comes back up with the same wan IP.  But the VOIP adapter cannot register until I manually delete the two states illustrated above (single:no_traffic and no_traffic:single, on ports 5060). 

I do have the state-killing box un-checked, and I see no evidence in syslog that rc.kill_states has ever run.

Reading through the commits in the bug, I see that rc.kill_states is only called from /usr/local/sbin/ppp-linkdown.  What about WAN links other than PPP?  How are the firewall states killed for those?  I guess that explains why it never gets called for me ...

Offline stephenw10

  • Administrator
  • Hero Member
  • *****
  • Posts: 11959
  • Karma: +469/-15
    • View Profile
Good point. You are using DHCP on WAN I take it?
The OP is using PPPoE though.  :-\

Steve

Offline charliem

  • Sr. Member
  • ****
  • Posts: 565
  • Karma: +43/-1
    • View Profile
Good point. You are using DHCP on WAN I take it?

Yes, DHCP on WAN, to Motorola Surfboard cable modem.  Hmm, what a coincidence, my cable modem re-booted itself last night a few hours after my last reply, so I didn't have to wait long.

Rather than try to pick out what's useful, here is my whole syslog from the time WAN went down until now, hope it's not too big.  In this log:
* 192.168.100.5, OPT1 on bge1_vlan2 is so I can browse to my cable modem on 192.168.100.1
* /dev/bge1 is WAN, DHCP to cable modem, shown as 24.74.xx.yyy below
* /dev/bge0 is LAN, static IP
* 24.74.32.1 is WAN gateway

Code: [Select]
Dec 14 19:40:49 pfsense sshd[76024]: Accepted keyboard-interactive/pam for root from 192.168.2.1 port 33826 ssh2
Dec 15 02:10:30 pfsense lighttpd[34032]: (connections.c.305) SSL: 1 error:1407609C:SSL routines:SSL23_GET_CLIENT_HELLO:http request
Dec 15 02:20:30 pfsense check_reload_status: Linkup starting bge1
Dec 15 02:20:30 pfsense kernel: bge1: link state changed to DOWN
Dec 15 02:20:30 pfsense kernel: bge1_vlan2: link state changed to DOWN
Dec 15 02:20:30 pfsense check_reload_status: Linkup starting bge1_vlan2
Dec 15 02:20:32 pfsense php: rc.linkup: DEVD Ethernet detached event for wan
Dec 15 02:20:32 pfsense php: rc.linkup: Hotplug event detected for OPT1(opt1) but ignoring since interface is configured with static IP (192.168.100.5 )
Dec 15 02:20:34 pfsense kernel: arpresolve: can't allocate llinfo for 24.74.32.1
Dec 15 02:20:35 pfsense kernel: arpresolve: can't allocate llinfo for 24.74.32.1
Dec 15 02:20:35 pfsense kernel: arpresolve: can't allocate llinfo for 24.74.32.1
Dec 15 02:20:36 pfsense kernel: arpresolve: can't allocate llinfo for 24.74.32.1
Dec 15 02:20:36 pfsense kernel: arpresolve: can't allocate llinfo for 24.74.32.1
Dec 15 02:20:36 pfsense kernel: arpresolve: can't allocate llinfo for 24.74.32.1
Dec 15 02:20:36 pfsense php: rc.linkup: Clearing states to old gateway 24.74.32.1.
Dec 15 02:20:37 pfsense kernel: arpresolve: can't allocate llinfo for 24.74.32.1
Dec 15 02:20:38 pfsense kernel: arpresolve: can't allocate llinfo for 24.74.32.1
Dec 15 02:20:39 pfsense kernel: arpresolve: can't allocate llinfo for 24.74.32.1
Dec 15 02:20:40 pfsense kernel: arpresolve: can't allocate llinfo for 24.74.32.1
Dec 15 02:20:41 pfsense kernel: arpresolve: can't allocate llinfo for 24.74.32.1
Dec 15 02:20:42 pfsense kernel: arpresolve: can't allocate llinfo for 24.74.32.1
Dec 15 02:20:43 pfsense kernel: arpresolve: can't allocate llinfo for 24.74.32.1
Dec 15 02:20:43 pfsense check_reload_status: Linkup starting bge1
Dec 15 02:20:43 pfsense kernel: bge1: link state changed to UP
Dec 15 02:20:43 pfsense kernel: bge1_vlan2: link state changed to UP
Dec 15 02:20:43 pfsense check_reload_status: Linkup starting bge1_vlan2
Dec 15 02:20:44 pfsense kernel: arpresolve: can't allocate llinfo for 24.74.32.1
Dec 15 02:20:45 pfsense kernel: arpresolve: can't allocate llinfo for 24.74.32.1
Dec 15 02:20:46 pfsense php: rc.linkup: DEVD Ethernet attached event for wan
Dec 15 02:20:46 pfsense php: rc.linkup: HOTPLUG: Configuring interface wan
Dec 15 02:20:46 pfsense php: rc.linkup: The command '/sbin/ifconfig 'bge1' inet  delete' returned exit code '1', the output was 'ifconfig: ioctl (SIOCDIFADDR): Can't assign requested address'
Dec 15 02:20:46 pfsense php: rc.linkup: Hotplug event detected for OPT1(opt1) but ignoring since interface is configured with static IP (192.168.100.5 )
Dec 15 02:20:46 pfsense check_reload_status: rc.newwanip starting bge1_vlan2
Dec 15 02:20:46 pfsense kernel: arpresolve: can't allocate llinfo for 24.74.32.1
Dec 15 02:20:47 pfsense kernel: arpresolve: can't allocate llinfo for 24.74.32.1
Dec 15 02:20:48 pfsense kernel: bge1: link state changed to DOWN
Dec 15 02:20:48 pfsense kernel: bge1_vlan2: link state changed to DOWN
Dec 15 02:20:48 pfsense check_reload_status: Linkup starting bge1
Dec 15 02:20:48 pfsense check_reload_status: Linkup starting bge1_vlan2
Dec 15 02:20:48 pfsense kernel: arpresolve: can't allocate llinfo for 24.74.32.1
Dec 15 02:20:48 pfsense php: rc.newwanip: rc.newwanip: Informational is starting bge1_vlan2.
Dec 15 02:20:48 pfsense php: rc.newwanip: rc.newwanip: on (IP address: 192.168.100.5) (interface: opt1) (real interface: bge1_vlan2).
Dec 15 02:20:48 pfsense check_reload_status: Reloading filter
Dec 15 02:20:49 pfsense kernel: arpresolve: can't allocate llinfo for 24.74.32.1
Dec 15 02:20:50 pfsense php: rc.linkup: DEVD Ethernet detached event for wan
Dec 15 02:20:50 pfsense php: rc.linkup: The command '/sbin/dhclient -c /var/etc/dhclient_wan.conf bge1 > /tmp/bge1_output 2> /tmp/bge1_error_output' returned exit code '15', the output was ''
Dec 15 02:20:50 pfsense php: rc.linkup: Accept router advertisements on interface bge1
Dec 15 02:20:50 pfsense check_reload_status: updating dyndns WAN_DHCP
Dec 15 02:20:50 pfsense check_reload_status: Restarting ipsec tunnels
Dec 15 02:20:50 pfsense check_reload_status: Restarting OpenVPN tunnels/interfaces
Dec 15 02:20:50 pfsense kernel: arpresolve: can't allocate llinfo for 24.74.32.1
Dec 15 02:20:50 pfsense php: rc.linkup: Hotplug event detected for OPT1(opt1) but ignoring since interface is configured with static IP (192.168.100.5 )
Dec 15 02:20:50 pfsense check_reload_status: Linkup starting bge1
Dec 15 02:20:50 pfsense kernel: bge1: link state changed to UP
Dec 15 02:20:50 pfsense kernel: bge1_vlan2: link state changed to UP
Dec 15 02:20:50 pfsense check_reload_status: Linkup starting bge1_vlan2
Dec 15 02:20:51 pfsense php: rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan).
Dec 15 02:20:51 pfsense php: rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan).
Dec 15 02:20:51 pfsense php: rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan).
Dec 15 02:20:51 pfsense php: rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan).
Dec 15 02:20:51 pfsense php: rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan).
Dec 15 02:20:51 pfsense php: rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan).
Dec 15 02:20:51 pfsense php: rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan).
Dec 15 02:20:51 pfsense kernel: arpresolve: can't allocate llinfo for 24.74.32.1
Dec 15 02:20:53 pfsense php: rc.linkup: DEVD Ethernet attached event for wan
Dec 15 02:20:53 pfsense php: rc.linkup: HOTPLUG: Configuring interface wan
Dec 15 02:20:53 pfsense php: rc.linkup: Hotplug event detected for OPT1(opt1) but ignoring since interface is configured with static IP (192.168.100.5 )
Dec 15 02:20:53 pfsense php: rc.linkup: The command '/sbin/ifconfig 'bge1' inet  delete' returned exit code '1', the output was 'ifconfig: ioctl (SIOCDIFADDR): Can't assign requested address'
Dec 15 02:20:53 pfsense check_reload_status: rc.newwanip starting bge1_vlan2
Dec 15 02:20:54 pfsense check_reload_status: updating dyndns wan
Dec 15 02:20:55 pfsense php: rc.newwanip: rc.newwanip: Informational is starting bge1_vlan2.
Dec 15 02:20:55 pfsense php: rc.newwanip: rc.newwanip: on (IP address: 192.168.100.5) (interface: opt1) (real interface: bge1_vlan2).
Dec 15 02:20:56 pfsense sshd[76024]: fatal: Write failed: Operation not permitted
Dec 15 02:20:56 pfsense sshd[76024]: fatal: Write failed: Operation not permitted
Dec 15 02:21:01 pfsense php: rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan).
Dec 15 02:21:01 pfsense php: rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan).
Dec 15 02:21:01 pfsense php: rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan).
Dec 15 02:21:01 pfsense php: rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan).
Dec 15 02:21:01 pfsense php: rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan).
Dec 15 02:21:01 pfsense php: rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan).
Dec 15 02:21:01 pfsense php: rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan).
Dec 15 02:21:08 pfsense php: rc.newipsecdns: IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing.
Dec 15 02:21:14 pfsense check_reload_status: rc.newwanip starting bge1
Dec 15 02:21:14 pfsense php: rc.linkup: Accept router advertisements on interface bge1
Dec 15 02:21:14 pfsense php: rc.linkup: ROUTING: setting default route to 24.74.32.1
Dec 15 02:21:17 pfsense php: rc.newwanip: rc.newwanip: Informational is starting bge1.
Dec 15 02:21:17 pfsense php: rc.newwanip: rc.newwanip: on (IP address: 24.74.xx.yyy) (interface: wan) (real interface: bge1).
Dec 15 02:21:17 pfsense php: rc.newwanip: ROUTING: setting default route to 24.74.32.1
Dec 15 02:21:17 pfsense php: rc.newwanip: Removing static route for monitor 8.8.8.8 and adding a new route through 24.74.32.1
Dec 15 02:21:17 pfsense check_reload_status: updating dyndns wan
Dec 15 02:21:18 pfsense php: rc.newipsecdns: Forcefully reloading IPsec racoon daemon
Dec 15 02:21:22 pfsense php: rc.newwanip: Forcefully reloading IPsec racoon daemon
Dec 15 02:21:22 pfsense php: rc.newwanip: Resyncing OpenVPN instances for interface WAN.
Dec 15 02:21:22 pfsense php: rc.newwanip: Creating rrd update script
Dec 15 02:21:24 pfsense php: rc.newwanip: pfSense package system has detected an ip change 24.74.xx.yyy ->  24.74.xx.yyy ... Restarting packages.
Dec 15 02:21:24 pfsense check_reload_status: Starting packages
Dec 15 02:21:24 pfsense check_reload_status: Reloading filter
Dec 15 02:21:25 pfsense check_reload_status: updating dyndns WAN_DHCP
Dec 15 02:21:25 pfsense check_reload_status: Restarting ipsec tunnels
Dec 15 02:21:25 pfsense check_reload_status: Restarting OpenVPN tunnels/interfaces
Dec 15 02:21:26 pfsense php: rc.start_packages: Restarting/Starting all packages.
Dec 15 02:21:31 pfsense lighttpd[34032]: (connections.c.1721) SSL (error): 5 -1 1 Operation not permitted
Dec 15 02:21:43 pfsense php: rc.newipsecdns: IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing.
Dec 15 02:21:53 pfsense php: rc.newipsecdns: Forcefully reloading IPsec racoon daemon
Dec 15 02:22:30 pfsense check_reload_status: Linkup starting bge1
Dec 15 02:22:30 pfsense kernel: bge1: link state changed to DOWN
Dec 15 02:22:30 pfsense kernel: bge1_vlan2: link state changed to DOWN
Dec 15 02:22:30 pfsense check_reload_status: Linkup starting bge1_vlan2
Dec 15 02:22:33 pfsense php: rc.linkup: DEVD Ethernet detached event for wan
Dec 15 02:22:33 pfsense php: rc.linkup: Hotplug event detected for OPT1(opt1) but ignoring since interface is configured with static IP (192.168.100.5 )
Dec 15 02:22:34 pfsense kernel: arpresolve: can't allocate llinfo for 24.74.32.1
Dec 15 02:22:35 pfsense kernel: arpresolve: can't allocate llinfo for 24.74.32.1
Dec 15 02:22:37 pfsense php: rc.linkup: Clearing states to old gateway 24.74.32.1.
Dec 15 02:22:43 pfsense check_reload_status: Linkup starting bge1
Dec 15 02:22:43 pfsense kernel: bge1: link state changed to UP
Dec 15 02:22:43 pfsense kernel: bge1_vlan2: link state changed to UP
Dec 15 02:22:43 pfsense check_reload_status: Linkup starting bge1_vlan2
Dec 15 02:22:46 pfsense php: rc.linkup: DEVD Ethernet attached event for wan
Dec 15 02:22:46 pfsense php: rc.linkup: HOTPLUG: Configuring interface wan
Dec 15 02:22:46 pfsense php: rc.linkup: Hotplug event detected for OPT1(opt1) but ignoring since interface is configured with static IP (192.168.100.5 )
Dec 15 02:22:46 pfsense check_reload_status: rc.newwanip starting bge1_vlan2
Dec 15 02:22:46 pfsense php: rc.linkup: The command '/sbin/ifconfig 'bge1' inet  delete' returned exit code '1', the output was 'ifconfig: ioctl (SIOCDIFADDR): Can't assign requested address'
Dec 15 02:22:47 pfsense check_reload_status: Linkup starting bge1
Dec 15 02:22:47 pfsense kernel: bge1: link state changed to DOWN
Dec 15 02:22:47 pfsense kernel: bge1_vlan2: link state changed to DOWN
Dec 15 02:22:47 pfsense check_reload_status: Linkup starting bge1_vlan2
Dec 15 02:22:48 pfsense php: rc.newwanip: rc.newwanip: Informational is starting bge1_vlan2.
Dec 15 02:22:48 pfsense php: rc.newwanip: rc.newwanip: on (IP address: 192.168.100.5) (interface: opt1) (real interface: bge1_vlan2).
Dec 15 02:22:48 pfsense check_reload_status: Reloading filter
Dec 15 02:22:49 pfsense check_reload_status: Linkup starting bge1
Dec 15 02:22:49 pfsense kernel: bge1: link state changed to UP
Dec 15 02:22:49 pfsense kernel: bge1_vlan2: link state changed to UP
Dec 15 02:22:49 pfsense check_reload_status: Linkup starting bge1_vlan2
Dec 15 02:22:49 pfsense php: rc.linkup: Hotplug event detected for OPT1(opt1) but ignoring since interface is configured with static IP (192.168.100.5 )
Dec 15 02:22:49 pfsense php: rc.linkup: DEVD Ethernet detached event for wan
Dec 15 02:22:49 pfsense php: rc.linkup: The command '/sbin/dhclient -c /var/etc/dhclient_wan.conf bge1 > /tmp/bge1_output 2> /tmp/bge1_error_output' returned exit code '15', the output was ''
Dec 15 02:22:49 pfsense php: rc.linkup: Accept router advertisements on interface bge1
Dec 15 02:22:50 pfsense check_reload_status: updating dyndns WAN_DHCP
Dec 15 02:22:50 pfsense check_reload_status: Restarting ipsec tunnels
Dec 15 02:22:50 pfsense check_reload_status: Restarting OpenVPN tunnels/interfaces
Dec 15 02:22:51 pfsense php: rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan).
Dec 15 02:22:51 pfsense php: rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan).
Dec 15 02:22:51 pfsense php: rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan).
Dec 15 02:22:51 pfsense php: rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan).
Dec 15 02:22:51 pfsense php: rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan).
Dec 15 02:22:51 pfsense php: rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan).
Dec 15 02:22:51 pfsense php: rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan).
Dec 15 02:22:52 pfsense php: rc.linkup: Hotplug event detected for OPT1(opt1) but ignoring since interface is configured with static IP (192.168.100.5 )
Dec 15 02:22:52 pfsense check_reload_status: rc.newwanip starting bge1_vlan2
Dec 15 02:22:52 pfsense php: rc.linkup: DEVD Ethernet attached event for wan
Dec 15 02:22:52 pfsense php: rc.linkup: HOTPLUG: Configuring interface wan
Dec 15 02:22:52 pfsense php: rc.linkup: The command '/sbin/ifconfig 'bge1' inet  delete' returned exit code '1', the output was 'ifconfig: ioctl (SIOCDIFADDR): Can't assign requested address'
Dec 15 02:22:53 pfsense check_reload_status: updating dyndns wan
Dec 15 02:22:54 pfsense php: rc.newwanip: rc.newwanip: Informational is starting bge1_vlan2.
Dec 15 02:22:54 pfsense php: rc.newwanip: rc.newwanip: on (IP address: 192.168.100.5) (interface: opt1) (real interface: bge1_vlan2).
Dec 15 02:23:00 pfsense php: rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan).
Dec 15 02:23:00 pfsense php: rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan).
Dec 15 02:23:00 pfsense php: rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan).
Dec 15 02:23:00 pfsense php: rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan).
Dec 15 02:23:00 pfsense php: rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan).
Dec 15 02:23:00 pfsense php: rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan).
Dec 15 02:23:00 pfsense php: rc.filter_configure_sync: Could not find IPv4 gateway for interface (wan).
Dec 15 02:23:08 pfsense php: rc.newipsecdns: IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing.
Dec 15 02:23:12 pfsense check_reload_status: rc.newwanip starting bge1
Dec 15 02:23:12 pfsense php: rc.linkup: Accept router advertisements on interface bge1
Dec 15 02:23:12 pfsense php: rc.linkup: ROUTING: setting default route to 24.74.32.1
Dec 15 02:23:15 pfsense php: rc.newwanip: rc.newwanip: Informational is starting bge1.
Dec 15 02:23:15 pfsense php: rc.newwanip: rc.newwanip: on (IP address: 24.74.xx.yyy) (interface: wan) (real interface: bge1).
Dec 15 02:23:15 pfsense php: rc.newwanip: ROUTING: setting default route to 24.74.32.1
Dec 15 02:23:15 pfsense php: rc.newwanip: Removing static route for monitor 8.8.8.8 and adding a new route through 24.74.32.1
Dec 15 02:23:16 pfsense check_reload_status: updating dyndns wan
Dec 15 02:23:18 pfsense php: rc.newipsecdns: Forcefully reloading IPsec racoon daemon
Dec 15 02:23:20 pfsense php: rc.newwanip: Forcefully reloading IPsec racoon daemon
Dec 15 02:23:20 pfsense php: rc.newwanip: Resyncing OpenVPN instances for interface WAN.
Dec 15 02:23:20 pfsense php: rc.newwanip: Creating rrd update script
Dec 15 02:23:22 pfsense php: rc.newwanip: pfSense package system has detected an ip change 24.74.xx.yyy ->  24.74.xx.yyy ... Restarting packages.
Dec 15 02:23:22 pfsense check_reload_status: Starting packages
Dec 15 02:23:22 pfsense check_reload_status: Reloading filter
Dec 15 02:23:23 pfsense check_reload_status: updating dyndns WAN_DHCP
Dec 15 02:23:23 pfsense check_reload_status: Restarting ipsec tunnels
Dec 15 02:23:23 pfsense check_reload_status: Restarting OpenVPN tunnels/interfaces
Dec 15 02:23:25 pfsense php: rc.start_packages: Restarting/Starting all packages.
Dec 15 02:23:41 pfsense php: rc.newipsecdns: IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing.
Dec 15 02:23:51 pfsense php: rc.newipsecdns: Forcefully reloading IPsec racoon daemon
Dec 15 04:31:14 pfsense lighttpd[34032]: (connections.c.305) SSL: 1 error:1407609C:SSL routines:SSL23_GET_CLIENT_HELLO:http request
Dec 15 08:23:36 pfsense sshd[32210]: Accepted keyboard-interactive/pam for root from 192.168.2.1 port 59083 ssh2

And here is my state table, filtered for 192.168.2.245 (my linksys VOIP adapter).  Attached (how to post images in-line?)




Offline stephenw10

  • Administrator
  • Hero Member
  • *****
  • Posts: 11959
  • Karma: +469/-15
    • View Profile
I've not dealt with this at all. You could try running rc.kill_states manually, looks like it needs some arguments passed to it, maybe:
Code: [Select]
/etc/rc.kill_states wan your_wan_IP_address
Doesn't help long term though.

Is this a known issue? Seems like it would be.

Steve

Edit: More discussion here: https://redmine.pfsense.org/issues/1629
Looks like a real fix will go in for 2.2.
« Last Edit: December 15, 2013, 08:37:29 am by stephenw10 »

Offline charliem

  • Sr. Member
  • ****
  • Posts: 565
  • Karma: +43/-1
    • View Profile
I've not dealt with this at all. You could try running rc.kill_states manually, looks like it needs some arguments passed to it, maybe:
Code: [Select]
/etc/rc.kill_states wan your_wan_IP_address
Doesn't help long term though.

Running it manually doesn't work.  It runs, but doesn't clear the states:
Code: [Select]
./rc.kill_states bge1 24.74.xx.yyy
puts this in syslog:
Dec 15 09:44:25 pfsense php: rc.kill_states: rc.kill_states: Removing states for IP 24.74.xx.yyy/32
Dec 15 09:44:25 pfsense php: rc.kill_states: rc.kill_states: Removing states for interface bge1

But old states are still there, and still no adapter registration.  States screenshot attached after running rc.kill_states manually.

Another strange problem is that ntpd is restarted, but takes 100% CPU until I go to 'Services --> ntp' and hit 'save'.  Screenshot attached, but that should be another thread unless it's related.

Quote
Is this a known issue? Seems like it would be.

Steve

Edit: More discussion here: https://redmine.pfsense.org/issues/1629
Looks like a real fix will go in for 2.2.

Well it's at least known to me and davros123  :)

Offline charliem

  • Sr. Member
  • ****
  • Posts: 565
  • Karma: +43/-1
    • View Profile
Edit: More discussion here: https://redmine.pfsense.org/issues/1629
Looks like a real fix will go in for 2.2.

Hmm:
Code: [Select]
#3181 is a band-aid for 2.1, this will need to wait 2.2
Would be nice if we could get a working band-aid, as it sounds like 2.2 is still a long way off.

Offline stephenw10

  • Administrator
  • Hero Member
  • *****
  • Posts: 11959
  • Karma: +469/-15
    • View Profile
You would have to feed it your old IP. Presumably this gets run when the gateway is detected as down rather than when when it is up again.

Steve

Offline charliem

  • Sr. Member
  • ****
  • Posts: 565
  • Karma: +43/-1
    • View Profile
You would have to feed it your old IP. Presumably this gets run when the gateway is detected as down rather than when when it is up again.

WAN IP doesn't change with my cable modem reset.  Well, generally it doesn't; I think it did once a few months ago, first time in 3-4 years.

Offline davros123

  • Jr. Member
  • **
  • Posts: 62
  • Karma: +3/-0
    • View Profile
So, any thoughts on what I should be looking at to debug this issue?

Offline charliem

  • Sr. Member
  • ****
  • Posts: 565
  • Karma: +43/-1
    • View Profile
So, any thoughts on what I should be looking at to debug this issue?

Seems the issues are well-understood, but the 'band-aid' fix put in for 2.1 was evidently not effective in cases like ours.  So debugging at this point would be to see why it's not effective in our cases.  Read through the history and associated revisions here:
https://redmine.pfsense.org/issues/1629 and
https://redmine.pfsense.org/issues/3181

There were some commits that reverted fixes that were deemed too excessive.  At this point, I'll take excessive, big-hammer type fixes, but I haven't had time to go back and try anything.

Offline davros123

  • Jr. Member
  • **
  • Posts: 62
  • Karma: +3/-0
    • View Profile
Thanks. When I get some time i'll put some debug code in there and see if I can work out why it is not clearing the states.

for now, my added kill code in ppp-linkup is working.

Offline charliem

  • Sr. Member
  • ****
  • Posts: 565
  • Karma: +43/-1
    • View Profile
OK, I have re-applied this commit  to my system.  It is the 'big hammer' approach, and I'm OK with that.  If you are using multi-WAN, you probably don't want this.

That patch was later backed out (with this) and a few minutes later further modified (with this) with the comment "Ticket #3181 do the state flushing only on down gateway detection rather than any time".

I believe something in the last patch broke the state killing on my system.  I'll follow up here next time my cable modem drops out.