[2.3.x] No default route on WAN PPPoE after link failure (with FIX, please test)



  • in the past days i post two thread about a problem with my pfSense installation with PPPoE fiber connection (Telecom Fibra). I have a bridged modem and pfSense made the authentication in PPPoE. With 2.2.6 it works without any kind of problem, with 2.3.x i have no internet connection, no ping, absolutely nothing.

    After some test, i find that after a link failure, pfSense lost default route on WAN (see attached "ko_default_route-png"). If i add manually (es: route add -net 0.0.0.0/0 79.19.236.134) all works (see "ok_default_route.png"), but my IP is dynamic, so when it changes internet connection get lost.

    With 2.2.6 default route works without problem. I don't know if is a issue of pfSense 2.3.x, but a make two different installation (x64 and Alix) and i had the same problem.
    Is there a way to add a workaround like adding a static default route on the PPPoE inferface instead of assigned PPPoE dynamic IP?

    EDIT: i found the way to add 0.0.0.0 static route to PPPoE interface: route add -net 0.0.0.0/0 -interface pppoe0. Is this a issue? Is there a way to fix, or make the route permanent?





  • I'm seeing the same thing. Up until 2.3.1_1 I didn't have a problem. 2.3.1_1 I had one incident which was resolved by a reboot. 2.3.1_5 never gets the route set up.

    Native IPv6 over the same link is fine, as is the ping test on the line (which is the only route entry in the IPv4 routing table).

    My configuration is a VMWare VM with the NIC passed through. Everything runs over VLANs on the NIC. PPPoE is using a 1500 baby-jumbo MTU.



  • I open a ticket with pfSense, and found a temporary workaround: https://redmine.pfsense.org/issues/6495 . In this way, code is like 2.2.6 and pfSense works without any problem.



  • Sounds like that gateway isn't marked as default under System>Routing, what does that screen look like?



  • Could be related: I noticed after upgrading Pfsense to todays minor updated, after the reboot the PPPoE interface said it was up, but no traffic was flowing, I had  to click 'disconnect' and 'reconnect' again under the interfaces, then all internet traffic started working again.

    From memory this has been a problem for quite some time, I'll see if I can find the original bug report.



  • @cmb:

    Sounds like that gateway isn't marked as default under System>Routing, what does that screen look like?

    Gateway is marked as default: i tried to edit config and then save too, but with no luck. The only way i find to solve issue (without adding manually a static route every PPPoE restart) was modifying /etc/inc/interfaces.inc like this:

    /* Omit this, we maintain the default route by other means, and it causes problems with * default gateway switching. See redmine #1837 */
    if (($interface "wan" && $founddefaultgw false) || $setdefaultgw == true) {
    $setdefaultgw = true;
    $mpdconf .= <<<eod<br>set iface route default
    
    EOD;</eod<br> 
    

    I remove the REM in this piece of code, so it looks like same file in pfSense 2.2.6. In this way if i reboot pfSense, disconnect WAN cable, reset (bridget) modem, disconnect/reconnect WAN interface, default route is created and all PC in my LAN have internet access.






  • @sammcj:

    […]
    From memory this has been a problem for quite some time, I'll see if I can find the original bug report.

    Yes, there is redmine #1837 ticket about a similar issue, but the proposed solution by editing the file (/etc/inc/interfaces.inc) stop the creation of the default gateway if the PPPoE session is disconnected. For this reason i modified the code and now it look like that in version 2.2.6 (which worked perfectly).

    Today i made some other test with my pfSense box (Atom 1037U CPU), an Alix, an HP DL380 end a portable DELL. My ISP is a 100/20 FTTC (Telecom Fibra). Same config: clean install, then restore from 2.2.6 config backup. Everybody have the same problems on PPPoE.



  • fyi - mine also has the default gateway set.



  • @cmb: do you think it would be possible to modify code so as to keep both version (2.2.6 and 2.3.x) in file /etc/inc/interfaces.inc? Code was modifyied in 2.3 for a issue (#1837) about multiwan gateway switching, but it seems to have problems with a single wan gateway config. In "single gateway mode" code would run set iface route default command, in "multi gateway mode" no.



  • I came back to pfsense having used another router while having this problem. Having started it up, I found that the PPP interface wouldn't come up. Looking under advanced config on the PPPoE link, no underlying interface was selected. Having set that the interface came up and routed correctly. I'll continue to monitor and see want happens when the underlaying DSL link fail cycles.



  • @jumpymonkey:

    I came back to pfsense having used another router while having this problem. Having started it up, I found that the PPP interface wouldn't come up. Looking under advanced config on the PPPoE link, no underlying interface was selected. Having set that the interface came up and routed correctly. I'll continue to monitor and see want happens when the underlaying DSL link fail cycles.

    Can you try the mod in /etc/inc/interfaces.inc i post?



  • It's working without the mod. I was about to try your mod, but now the interface is up and working as expected. I'll see what happens when I pull the modem link out later, and if that stops the routing working I'll apply the mod.



  • @jumpymonkey:

    It's working without the mod. I was about to try your mod, but now the interface is up and working as expected. I'll see what happens when I pull the modem link out later, and if that stops the routing working I'll apply the mod.

    What happened if you disconnect and riconnect WAN or PPPoE cable from modem?



  • I cycled the modem. When the link came back up, the I couldn't connect out to the Internet. Adding your fix and cycling the PPPoE link fixes the problem. Thanks!



  • @jumpymonkey:

    I cycled the modem. When the link came back up, the I couldn't connect out to the Internet. Adding your fix and cycling the PPPoE link fixes the problem. Thanks!

    Well, my fix is actually the same code present in 2.2.6, that works without problem. Thank you for test.  :)



  • Is there a redmine on this?





  • OK, for pfSense people to take this seriously you'll have to create it as a patch here:
    https://github.com/pfsense/pfsense

    Just register, choose your file, click the pencil icon to edit it, and it will create a fork for you. Then, submit a pull request for your fork. In the description, link to this topic and the redmine issue.



  • @robi:

    OK, for pfSense people to take this seriously you'll have to create it as a patch here:
    https://github.com/pfsense/pfsense

    Just register, choose your file, click the pencil icon to edit it, and it will create a fork for you. Then, submit a pull request for your fork. In the description, link to this topic and the redmine issue.

    Hi Roby, i'm not a PHP developer, so i don't think it's a good idea modify code on my own. Anyway, in redmine #6495 i suggested a possibile change about code:

    if ONE GW then
        <the code="" i="" modify="">else (TWO or MORE GW)
        endif</the>
    `In this way it could work both configuration, one WAN gateway or two (or more).

    P.S. What do you mean for "…for pfSense people to take this seriously"?`



  • You said "my fix is actually the same code…" - I thougt you have a real fix for the problem...

    As far as I noticed over the years, code snippets posted on the forum almost never reach to be in the actual product.



  • @robi:

    You said "my fix is actually the same code…" - I thougt you have a real fix for the problem...

    As far as I noticed over the years, code snippets posted on the forum almost never reach to be in the actual product.

    As you can read in my reply to jumpymonkey, my fix is simply the recovery of the code of 2.2.6, that not rem the line set iface route default. But as said in Redmine #1837, 2.2.6 code works well with one WAN gateway, but create problems with multi WAN gateway configuration. So i thought multi choice <if…else...endif>would be a good solution.</if…else...endif>



  • OK, the problem that this is all so confusing with your fix. Sorry.

    I don't mean to to offend you with this, just trying to help. Which file, which line number should be replaced with what.
    PHP is so easy…



  • @robi:

    OK, the problem that this is all so confusing with your fix. Sorry.

    I don't mean to to hurt you with this, just trying to help. Which file, which line number should be replaced with what.
    PHP is so easy…

    Hi robi, really, there's absolutely no problem, why should be hurt?  :)  I'm not a PHP developer (i'm a network admin) and at office i managed 14 (16) pfSense box with WAN static IP. But i have pfSense at home too with PPPoE connection, and from 2.3 release i have several problem with auth. I have a little bit of knowledge of programming, so i try to investigate and finally i found redmine #1837 and so on.

    I start to learn PHP, but I think it is still early and I'm not at an advanced level as the official team, so I think it's better to just report the bug.  ;) ;)

    File is /etc/inc/interfaces.inc from line 1806 to line 1815.

    Thanks in advance.  :)



  • @robi:

    OK, for pfSense people to take this seriously you'll have to create it as a patch here:
    https://github.com/pfsense/pfsense

    Not true, there is a bug open and we'll get a proper fix. Going back to the change discussed in this thread will regress other things and isn't right. We need to track down the real source of the issue and fix that. I can't replicate it at all though, so going to need some help from those who can.

    mpd calls ppp-linkup after connecting, which triggers rc.newwanip. rc.newwanip sets the default gateway.

    When you're left with no default gateway after a reconnect, check the system log. What is there from rc.newwanip? Should see something like:

    rc.newwanip: ROUTING: setting default route to x.x.x.x
    

    is that there? What else is logged at the time?

    If you cause the WAN NIC to lose its link, in addition to rc.newwanip, rc.linkup will also set the default gateway and have a similar log. So you'll see it twice in that case, which is fine.

    Note I'm talking about using strictly stock source code, not the change in this thread. Revert that change first if you made it.



  • @cmb:

    […]
    When you're left with no default gateway after a reconnect, check the system log. What is there from rc.newwanip? Should see something like:

    rc.newwanip: ROUTING: setting default route to x.x.x.x
    

    is that there? What else is logged at the time?

    If you cause the WAN NIC to lose its link, in addition to rc.newwanip, rc.linkup will also set the default gateway and have a similar log. So you'll see it twice in that case, which is fine.

    Note I'm talking about using strictly stock source code, not the change in this thread. Revert that change first if you made it.

    Hi Cmb,
    thanks for your post. I'll try and post the log.  :)

    Actually i can test with 3 PPPoE ISP provider and 1 PPPoA (converted by modem in PPPoE) ISP and four different hardware (Alix, APU, x64 a i386). I follow redmine #6495 status, as soon as a fix is posted, i'll try and let you know.

    Thanks in advance,


    Marlenio



  • @cmb:

    […]
    When you're left with no default gateway after a reconnect, check the system log. What is there from rc.newwanip? Should see something like:

    rc.newwanip: ROUTING: setting default route to x.x.x.x
    

    is that there? What else is logged at the time?

    If you cause the WAN NIC to lose its link, in addition to rc.newwanip, rc.linkup will also set the default gateway and have a similar log. So you'll see it twice in that case, which is fine.

    Note I'm talking about using strictly stock source code, not the change in this thread. Revert that change first if you made it.

    Hi cmb, i revert the change, clear log and disconnect/reconnect PPPoE WAN interface. Here is the log. Look at line 71/72:

    
    Jun 22 20:13:08	php-fpm	40496	/rc.dyndns.update: Curl error occurred: Could not resolve host: ipv4.tunnelbroker.net
    Jun 22 20:13:07	php-fpm	31985	/rc.newwanip: Curl error occurred: Could not resolve host: freedns.afraid.org
    Jun 22 20:13:07	php-fpm	31985	/rc.newwanip: Dynamic DNS freedns (casalener.mooo.com): _checkStatus() starting.
    Jun 22 20:13:00	xinetd	14152	Reconfigured: new=0 old=1 dropped=0 (services)
    Jun 22 20:13:00	xinetd	14152	readjusting service 6969-udp
    Jun 22 20:13:00	xinetd	14152	Swapping defaults
    Jun 22 20:13:00	xinetd	14152	Starting reconfiguration
    Jun 22 20:12:59	php-fpm	31985	/rc.newwanip: Dynamic DNS freedns (casalener.mooo.com): _update() starting.
    Jun 22 20:12:59	php-fpm	31985	/rc.newwanip: DynDns (casalener.mooo.com): Dynamic Dns: cacheIP != wan_ip. Updating. Cached IP: 82.51.169.204 WAN IP: 79.17.44.55
    Jun 22 20:12:59	php-fpm	31985	/rc.newwanip: Dynamic Dns (casalener.mooo.com): Current WAN IP: 79.17.44.55 Cached IP: 82.51.169.204
    Jun 22 20:12:59	php-fpm	31985	/rc.newwanip: Dynamic DNS freedns (casalener.mooo.com): 79.17.44.55 extracted from local system.
    Jun 22 20:12:59	php-fpm	31985	/rc.newwanip: Dynamic DNS (casalener.mooo.com): running get_failover_interface for wan. found pppoe1
    Jun 22 20:12:59	php-fpm	31985	/rc.newwanip: Dynamic DNS freedns (casalener.mooo.com): 79.17.44.55 extracted from local system.
    Jun 22 20:12:59	php-fpm	40496	/rc.dyndns.update: Curl error occurred: Could not resolve host: freedns.afraid.org
    Jun 22 20:12:59	php-fpm	40496	/rc.dyndns.update: Dynamic DNS freedns (casalener.mooo.com): _checkStatus() starting.
    Jun 22 20:12:59	php-fpm	31985	/rc.newwanip: Dynamic DNS: updatedns() starting
    Jun 22 20:12:58	xinetd	14152	Reconfigured: new=0 old=1 dropped=0 (services)
    Jun 22 20:12:58	xinetd	14152	readjusting service 6969-udp
    Jun 22 20:12:58	xinetd	14152	Swapping defaults
    Jun 22 20:12:58	xinetd	14152	Starting reconfiguration
    Jun 22 20:12:58	check_reload_status		Reloading filter
    Jun 22 20:12:58	php-fpm	24848	/rc.newipsecdns: IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing.
    Jun 22 20:12:58	php-fpm	31985	/rc.newwanip: Curl error occurred: Could not resolve host: dynupdate.no-ip.com
    Jun 22 20:12:57	xinetd	14152	Reconfigured: new=0 old=1 dropped=0 (services)
    Jun 22 20:12:57	xinetd	14152	readjusting service 6969-udp
    Jun 22 20:12:57	xinetd	14152	Swapping defaults
    Jun 22 20:12:57	xinetd	14152	Starting reconfiguration
    Jun 22 20:12:56	xinetd	14152	Reconfigured: new=0 old=1 dropped=0 (services)
    Jun 22 20:12:56	xinetd	14152	readjusting service 6969-udp
    Jun 22 20:12:56	xinetd	14152	Swapping defaults
    Jun 22 20:12:56	xinetd	14152	Starting reconfiguration
    Jun 22 20:12:56	check_reload_status		Reloading filter
    Jun 22 20:12:56	php-fpm	46306	/rc.newipsecdns: IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing.
    Jun 22 20:12:50	php-fpm	40496	/rc.dyndns.update: Dynamic DNS freedns (casalener.mooo.com): _update() starting.
    Jun 22 20:12:50	php-fpm	40496	/rc.dyndns.update: DynDns (casalener.mooo.com): Dynamic Dns: cacheIP != wan_ip. Updating. Cached IP: 82.51.169.204 WAN IP: 79.17.44.55
    Jun 22 20:12:50	php-fpm	40496	/rc.dyndns.update: Dynamic Dns (casalener.mooo.com): Current WAN IP: 79.17.44.55 Cached IP: 82.51.169.204
    Jun 22 20:12:50	php-fpm	40496	/rc.dyndns.update: Dynamic DNS freedns (casalener.mooo.com): 79.17.44.55 extracted from local system.
    Jun 22 20:12:50	php-fpm	40496	/rc.dyndns.update: Dynamic DNS (casalener.mooo.com): running get_failover_interface for wan. found pppoe1
    Jun 22 20:12:50	php-fpm	40496	/rc.dyndns.update: Dynamic DNS freedns (casalener.mooo.com): 79.17.44.55 extracted from local system.
    Jun 22 20:12:50	php-fpm	40496	/rc.dyndns.update: Dynamic DNS: updatedns() starting
    Jun 22 20:12:49	php-fpm	40496	/rc.dyndns.update: Curl error occurred: Could not resolve host: dynupdate.no-ip.com
    Jun 22 20:12:43	kernel		gif0: link state changed to UP
    Jun 22 20:12:43	kernel		gif0: link state changed to DOWN
    Jun 22 20:12:43	php-fpm	24848	/status_interfaces.php: ROUTING: setting IPv6 default route to 2001:470:1f12:62c::1
    Jun 22 20:12:39	check_reload_status		Reloading filter
    Jun 22 20:12:39	check_reload_status		Restarting OpenVPN tunnels/interfaces
    Jun 22 20:12:39	check_reload_status		Reloading filter
    Jun 22 20:12:39	check_reload_status		Restarting ipsec tunnels
    Jun 22 20:12:39	check_reload_status		Restarting OpenVPN tunnels/interfaces
    Jun 22 20:12:39	check_reload_status		updating dyndns WAN_PPPOE
    Jun 22 20:12:39	check_reload_status		Restarting ipsec tunnels
    Jun 22 20:12:39	check_reload_status		updating dyndns HE_IPV6_TUNNELV6
    Jun 22 20:12:37	ppp		[wan] IPV6CP: LayerFinish
    Jun 22 20:12:37	ppp		[wan] IPV6CP: state change Stopping --> Stopped
    Jun 22 20:12:36	php-fpm	31985	/rc.newwanip: Removing static route for monitor 2001:4860:4860::8888 and adding a new route through 2001:470:1f12:62c::1
    Jun 22 20:12:36	php-fpm	40496	/rc.resolv_conf_generate: The command '/sbin/route delete -host 208.67.220.220 ' returned exit code '1', the output was 'route: writing to routing socket: No such process delete host 208.67.220.220 fib 0: not in table'
    Jun 22 20:12:36	php-fpm	40496	/rc.resolv_conf_generate: The command '/sbin/route delete -host 208.67.222.222 ' returned exit code '1', the output was 'route: writing to routing socket: No such process delete host 208.67.222.222 fib 0: not in table'
    Jun 22 20:12:36	php-fpm	40496	/rc.newwanipv6: rc.newwanipv6: No IPv6 address found for interface WAN [wan].
    Jun 22 20:12:36	php-fpm	40496	/rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe1.
    Jun 22 20:12:35	xinetd	14152	Reconfigured: new=0 old=1 dropped=0 (services)
    Jun 22 20:12:35	xinetd	14152	readjusting service 6969-udp
    Jun 22 20:12:35	xinetd	14152	Swapping defaults
    Jun 22 20:12:35	xinetd	14152	Starting reconfiguration
    Jun 22 20:12:35	php-fpm	31985	/rc.newwanip: IP has changed, killing states on former IP 87.1.223.208.
    Jun 22 20:12:35	kernel		gif0: link state changed to UP
    Jun 22 20:12:35	kernel		gif0: link state changed to DOWN
    Jun 22 20:12:35	php-fpm	31985	/rc.newwanip: ROUTING: setting IPv6 default route to 2001:470:1f12:62c::1
    Jun 22 20:12:35	kernel		gif0: link state changed to UP
    Jun 22 20:12:35	kernel		gif0: link state changed to DOWN
    Jun 22 20:12:35	php-fpm	31985	/rc.newwanip: ROUTING: setting IPv6 default route to 2001:470:1f12:62c::1
    Jun 22 20:12:35	php-fpm	31985	/rc.newwanip: The command '/sbin/route delete -host 208.67.220.220 ' returned exit code '1', the output was 'route: writing to routing socket: No such process delete host 208.67.220.220 fib 0: not in table'
    Jun 22 20:12:35	php-fpm	31985	/rc.newwanip: The command '/sbin/route delete -host 208.67.222.222 ' returned exit code '1', the output was 'route: writing to routing socket: No such process delete host 208.67.222.222 fib 0: not in table'
    Jun 22 20:12:35	php-fpm	31985	/rc.newwanip: rc.newwanip: on (IP address: 79.17.44.55) (interface: WAN[wan]) (real interface: pppoe1).
    Jun 22 20:12:35	php-fpm	31985	/rc.newwanip: rc.newwanip: Info: starting on pppoe1.
    Jun 22 20:12:34	check_reload_status		Rewriting resolv.conf
    Jun 22 20:12:34	ppp		[wan] IPV6CP: LayerDown
    Jun 22 20:12:34	ppp		[wan] IPV6CP: SendTerminateAck #2
    Jun 22 20:12:34	ppp		[wan] IPV6CP: state change Opened --> Stopping
    Jun 22 20:12:34	ppp		[wan] IPV6CP: rec'd Terminate Request #91 (Opened)
    Jun 22 20:12:34	check_reload_status		rc.newwanipv6 starting pppoe1
    Jun 22 20:12:34	ppp		[wan] 76d4:35ff:fe8a:b19c -> 02a0:a50f:fc86:8004
    Jun 22 20:12:34	ppp		[wan] IPV6CP: LayerUp
    Jun 22 20:12:34	ppp		[wan] IPV6CP: state change Ack-Rcvd --> Opened
    Jun 22 20:12:34	ppp		[wan] IPV6CP: SendConfigAck #90
    Jun 22 20:12:34	ppp		[wan] IPV6CP: rec'd Configure Request #90 (Ack-Rcvd)
    Jun 22 20:12:34	ppp		[wan] IFACE: Rename interface ng0 to pppoe1
    Jun 22 20:12:34	ppp		[wan] IFACE: Up event
    Jun 22 20:12:34	check_reload_status		rc.newwanip starting pppoe1
    Jun 22 20:12:34	ppp		[wan] 79.17.44.55 -> 192.168.100.1
    Jun 22 20:12:34	ppp		[wan] IPCP: LayerUp
    Jun 22 20:12:34	ppp		[wan] IPCP: state change Ack-Rcvd --> Opened
    Jun 22 20:12:34	ppp		[wan] IPADDR 192.168.100.1
    Jun 22 20:12:34	ppp		[wan] IPCP: SendConfigAck #26
    Jun 22 20:12:34	ppp		[wan] 192.168.100.1 is OK
    Jun 22 20:12:34	ppp		[wan] IPADDR 192.168.100.1
    Jun 22 20:12:34	ppp		[wan] IPCP: rec'd Configure Request #26 (Ack-Rcvd)
    Jun 22 20:12:34	ppp		[wan] IPCP: state change Req-Sent --> Ack-Rcvd
    Jun 22 20:12:34	ppp		[wan] IPADDR 79.17.44.55
    Jun 22 20:12:34	ppp		[wan] IPCP: rec'd Configure Ack #3 (Req-Sent)
    Jun 22 20:12:34	ppp		[wan] IPADDR 79.17.44.55
    Jun 22 20:12:34	ppp		[wan] IPCP: SendConfigReq #3
    Jun 22 20:12:34	ppp		[wan] 79.17.44.55 is OK
    Jun 22 20:12:34	ppp		[wan] IPADDR 79.17.44.55
    Jun 22 20:12:34	ppp		[wan] IPCP: rec'd Configure Nak #2 (Req-Sent)
    Jun 22 20:12:34	ppp		[wan] IPV6CP: state change Req-Sent --> Ack-Rcvd
    Jun 22 20:12:34	ppp		[wan] IPV6CP: rec'd Configure Ack #1 (Req-Sent)
    Jun 22 20:12:34	ppp		[wan] IPADDR 0.0.0.0
    Jun 22 20:12:34	ppp		[wan] IPCP: SendConfigReq #2
    Jun 22 20:12:34	ppp		[wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
    Jun 22 20:12:34	ppp		[wan] IPCP: rec'd Configure Reject #1 (Req-Sent)
    Jun 22 20:12:34	ppp		[wan] IPV6CP: SendConfigReq #1
    Jun 22 20:12:34	ppp		[wan] IPV6CP: state change Starting --> Req-Sent
    Jun 22 20:12:34	ppp		[wan] IPV6CP: Up event
    Jun 22 20:12:34	ppp		[wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
    Jun 22 20:12:34	ppp		[wan] IPADDR 0.0.0.0
    Jun 22 20:12:34	ppp		[wan] IPCP: SendConfigReq #1
    Jun 22 20:12:34	ppp		[wan] IPCP: state change Starting --> Req-Sent
    Jun 22 20:12:34	ppp		[wan] IPCP: Up event
    Jun 22 20:12:34	ppp		[wan] IPV6CP: LayerStart
    Jun 22 20:12:34	ppp		[wan] IPV6CP: state change Initial --> Starting
    Jun 22 20:12:34	ppp		[wan] IPV6CP: Open event
    Jun 22 20:12:34	ppp		[wan] IPCP: LayerStart
    Jun 22 20:12:34	ppp		[wan] IPCP: state change Initial --> Starting
    Jun 22 20:12:34	ppp		[wan] IPCP: Open event
    Jun 22 20:12:34	ppp		[wan] Bundle: Status update: up 1 link, total bandwidth 64000 bps
    Jun 22 20:12:34	ppp		[wan_link0] Link: Join bundle "wan"
    Jun 22 20:12:34	ppp		[wan_link0] Link: Matched action 'bundle "wan" ""'
    Jun 22 20:12:34	ppp		[wan_link0] LCP: authorization successful
    Jun 22 20:12:34	ppp		[wan_link0] PAP: rec'd ACK #1 len: 5
    Jun 22 20:12:34	ppp		[wan_link0] LCP: LayerUp
    Jun 22 20:12:34	ppp		[wan_link0] PAP: sending REQUEST #1 len: 24
    Jun 22 20:12:34	ppp		[wan_link0] PAP: using authname "aliceadsl"
    Jun 22 20:12:34	ppp		[wan_link0] LCP: auth: peer wants PAP, I want nothing
    Jun 22 20:12:34	ppp		[wan_link0] LCP: state change Ack-Sent --> Opened
    Jun 22 20:12:34	ppp		[wan_link0] MAGICNUM 0x30806941
    Jun 22 20:12:34	ppp		[wan_link0] MRU 1492
    Jun 22 20:12:34	ppp		[wan_link0] PROTOCOMP
    Jun 22 20:12:34	ppp		[wan_link0] LCP: rec'd Configure Ack #1 (Ack-Sent)
    Jun 22 20:12:34	ppp		[wan_link0] LCP: state change Req-Sent --> Ack-Sent
    Jun 22 20:12:34	ppp		[wan_link0] MAGICNUM 0x0107258b
    Jun 22 20:12:34	ppp		[wan_link0] AUTHPROTO PAP
    Jun 22 20:12:34	ppp		[wan_link0] MRU 1492
    Jun 22 20:12:34	ppp		[wan_link0] LCP: SendConfigAck #48
    Jun 22 20:12:34	ppp		[wan_link0] MAGICNUM 0x0107258b
    Jun 22 20:12:34	ppp		[wan_link0] AUTHPROTO PAP
    Jun 22 20:12:34	ppp		[wan_link0] MRU 1492
    Jun 22 20:12:34	ppp		[wan_link0] LCP: rec'd Configure Request #48 (Req-Sent)
    Jun 22 20:12:34	ppp		[wan_link0] MAGICNUM 0x30806941
    Jun 22 20:12:34	ppp		[wan_link0] MRU 1492
    Jun 22 20:12:34	ppp		[wan_link0] PROTOCOMP
    Jun 22 20:12:34	ppp		[wan_link0] LCP: SendConfigReq #1
    Jun 22 20:12:34	ppp		[wan_link0] LCP: state change Starting --> Req-Sent
    Jun 22 20:12:34	ppp		[wan_link0] LCP: Up event
    Jun 22 20:12:34	ppp		[wan_link0] Link: UP event
    Jun 22 20:12:34	ppp		[wan_link0] PPPoE: connection successful
    Jun 22 20:12:33	ppp		PPPoE: rec'd ACNAME "r-rm900"
    Jun 22 20:12:33	ppp		[wan_link0] PPPoE: Connecting to 'TelecomFibra'
    Jun 22 20:12:33	ppp		[wan_link0] LCP: LayerStart
    Jun 22 20:12:33	ppp		[wan_link0] LCP: state change Initial --> Starting
    Jun 22 20:12:33	ppp		[wan_link0] LCP: Open event
    Jun 22 20:12:33	kernel		ng0: changing name to 'pppoe1'
    Jun 22 20:12:33	ppp		[wan_link0] Link: OPEN event
    Jun 22 20:12:33	ppp		[wan] Bundle: Interface ng0 created
    Jun 22 20:12:33	ppp		web: web is not running
    Jun 22 20:12:33	ppp		process 31483 started, version 5.8 (root@pfSense_v2_3_1_amd64-pfSense_v2_3_1-job-13 19:20 16-May-2016)
    Jun 22 20:12:33	ppp		Multi-link PPP daemon for FreeBSD
    Jun 22 20:12:29	ppp		process 5179 terminated
    Jun 22 20:12:29	ppp		[wan_link0] Link: Shutdown
    Jun 22 20:12:29	ppp		[wan] Bundle: Shutdown
    [b]Jun 22 20:12:28	php-fpm	24848	/rc.resolv_conf_generate: The command '/sbin/route delete -host 208.67.220.220 ' returned exit code '1', the output was 'route: writing to routing socket: No such process delete host 208.67.220.220 fib 0: not in table'
    Jun 22 20:12:28	php-fpm	24848	/rc.resolv_conf_generate: The command '/sbin/route delete -host 208.67.222.222 ' returned exit code '1', the output was 'route: writing to routing socket: No such process delete host 208.67.222.222 fib 0: not in table'[/b]
    Jun 22 20:12:27	ppp		[wan_link0] LCP: state change Stopping --> Closing
    Jun 22 20:12:27	ppp		[wan_link0] LCP: Close event
    Jun 22 20:12:27	ppp		[wan_link0] Link: CLOSE event
    Jun 22 20:12:27	ppp		[wan_link0] LCP: LayerDown
    Jun 22 20:12:27	ppp		[wan_link0] LCP: SendTerminateAck #2
    Jun 22 20:12:27	ppp		[wan] IPV6CP: state change Closed --> Initial
    Jun 22 20:12:27	ppp		[wan] IPV6CP: Down event
    Jun 22 20:12:27	ppp		[wan] IPCP: state change Closed --> Initial
    Jun 22 20:12:27	ppp		[wan] IPCP: Down event
    Jun 22 20:12:27	ppp		[wan] IPV6CP: Close event
    Jun 22 20:12:27	ppp		[wan] IPCP: Close event
    Jun 22 20:12:27	ppp		[wan] Bundle: Status update: up 0 links, total bandwidth 9600 bps
    Jun 22 20:12:27	ppp		[wan_link0] Link: Leave bundle "wan"
    Jun 22 20:12:27	ppp		[wan_link0] LCP: state change Opened --> Stopping
    Jun 22 20:12:27	ppp		[wan_link0] LCP: rec'd Terminate Request #109 (Opened)
    Jun 22 20:12:27	ppp		[wan] Bundle: closing link "wan_link0"...
    Jun 22 20:12:27	ppp		[wan] Bundle: No NCPs left. Closing links...
    Jun 22 20:12:27	ppp		[wan] IPCP: LayerFinish
    Jun 22 20:12:27	ppp		[wan] IPCP: state change Closing --> Closed
    Jun 22 20:12:27	ppp		[wan] IPCP: rec'd Terminate Ack #4 (Closing)
    Jun 22 20:12:27	ppp		[wan] IPV6CP: state change Stopped --> Closed
    Jun 22 20:12:27	ppp		[wan] IPV6CP: Close event
    Jun 22 20:12:27	ppp		[wan] IFACE: Rename interface pppoe1 to pppoe1
    Jun 22 20:12:27	ppp		[wan] IFACE: Down event
    Jun 22 20:12:27	check_reload_status		Rewriting resolv.conf
    Jun 22 20:12:27	ppp		[wan] IPCP: LayerDown
    Jun 22 20:12:27	ppp		[wan] IPCP: SendTerminateReq #4
    Jun 22 20:12:27	ppp		[wan] IPCP: state change Opened --> Closing
    Jun 22 20:12:27	ppp		[wan] IPCP: Close event
    Jun 22 20:12:27	ppp		[wan] IFACE: Close event
    Jun 22 20:12:27	ppp		caught fatal signal TERM
    Jun 22 20:12:20	syslogd		kernel boot file is /boot/kernel/kernel
    
    

    208.67.222.222 and 208.67.220.200 are my OpenDNS name server. IPv6 Tunnel is from HE.

    Thanks in advance,



  • Hello all,

    I'm having the same issue. Since 2.3.1 (up to 2.3.1_5), folowing a reboot, no default gateway and no Internet access.

    No line similar to "ROUTING: setting default route to x.x.x.x" in the log. (cmb, I can send the log to you if required.)

    However, going to System -> Routing -> Gateways and editing and saving the automatically created PPPoE default gateway entry creates it and everything is back up.

    My capabilities for testing are limited as this is a production system and I only have remote access to it but I'll be glad to help if I can.

    Thanks.



  • @Marlenio:

    Hi cmb, i revert the change, clear log and disconnect/reconnect PPPoE WAN interface. Here is the log. Look at line 71/72:

    Thanks for the logs, that helps. The route delete errors there are fine, just because the routes were dropped as part of PPP disconnecting so they aren't there to delete.

    ppp-linkup calls rc.newwanip, which calls system_routing_configure. If it had an interface, and gateway IP, it would be adding it there. It's not apparent which it could be missing. Next, in /etc/inc/system.inc above this line:

    if ($dont_add_route == false) {
    

    add this line:

    log_error("DEBUG: interface: $interface interfacegw: $interfacegw gatewayip: $gatewayip");
    

    Then replicate again, and post the new logs.



  • Hi cmb,

    @cmb:

    […]
    add this line:

    log_error("DEBUG: interface: $interface interfacegw: $interfacegw gatewayip: $gatewayip");
    

    Then replicate again, and post the new logs.

    I change /etc/inc/system.inc:

    
            /* La linea seguente è stata aggiunta per il debug dell'errore Redmine #6495 */
            log_error("DEBUG: interface: $interface interfacegw: $interfacegw gatewayip: $gatewayip");         
    	if ($dont_add_route == false) {
    		if (!empty($interface) && $interface != $interfacegw) {
    
    

    This is system log with  strictly stock source:

    
    Jun 24 10:38:03	xinetd	14152	Reconfigured: new=0 old=1 dropped=0 (services)
    Jun 24 10:38:03	xinetd	14152	readjusting service 6969-udp
    Jun 24 10:38:03	xinetd	14152	Swapping defaults
    Jun 24 10:38:03	xinetd	14152	Starting reconfiguration
    Jun 24 10:38:02	xinetd	14152	Reconfigured: new=0 old=1 dropped=0 (services)
    Jun 24 10:38:02	xinetd	14152	readjusting service 6969-udp
    Jun 24 10:38:02	xinetd	14152	Swapping defaults
    Jun 24 10:38:02	xinetd	14152	Starting reconfiguration
    Jun 24 10:38:01	ftp-proxy	5586	listening on 127.0.0.1 port 8021
    Jun 24 10:38:01	check_reload_status		Reloading filter
    Jun 24 10:38:01	check_reload_status		Syncing firewall
    Jun 24 10:38:01	php-fpm	98299	[pfBlockerNG] Starting cron process.
    Jun 24 10:38:01	ftp-proxy	2171	listening on 127.0.0.1 port 8021
    Jun 24 10:38:01	check_reload_status		Reloading filter
    Jun 24 10:38:01	php-fpm	98299	/rc.start_packages: Restarting/Starting all packages.
    Jun 24 10:38:00	check_reload_status		Starting packages
    Jun 24 10:38:00	php-fpm	65464	/rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - 79.47.194.62 -> 79.56.147.131 - Restarting packages.
    Jun 24 10:37:59	xinetd	14152	Reconfigured: new=0 old=1 dropped=0 (services)
    Jun 24 10:37:59	xinetd	14152	readjusting service 6969-udp
    Jun 24 10:37:59	xinetd	14152	Swapping defaults
    Jun 24 10:37:59	xinetd	14152	Starting reconfiguration
    Jun 24 10:37:58	php-fpm	65464	/rc.newwanip: Creating rrd update script
    Jun 24 10:37:58	php-fpm	65464	/rc.newwanip: Resyncing OpenVPN instances for interface WAN.
    Jun 24 10:37:58	check_reload_status		Reloading filter
    Jun 24 10:37:58	php-fpm	65464	/rc.newwanip: Forcefully reloading IPsec
    Jun 24 10:37:57	php-fpm	65464	/rc.newwanip: Curl error occurred: Could not resolve host: ipv4.tunnelbroker.net
    Jun 24 10:37:54	xinetd	14152	Reconfigured: new=0 old=1 dropped=0 (services)
    Jun 24 10:37:54	xinetd	14152	readjusting service 6969-udp
    Jun 24 10:37:54	xinetd	14152	Swapping defaults
    Jun 24 10:37:54	xinetd	14152	Starting reconfiguration
    Jun 24 10:37:53	check_reload_status		Reloading filter
    Jun 24 10:37:53	php-fpm	55525	/rc.newipsecdns: IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing.
    Jun 24 10:37:51	xinetd	14152	Reconfigured: new=0 old=1 dropped=0 (services)
    Jun 24 10:37:51	xinetd	14152	readjusting service 6969-udp
    Jun 24 10:37:51	xinetd	14152	Swapping defaults
    Jun 24 10:37:51	xinetd	14152	Starting reconfiguration
    Jun 24 10:37:50	xinetd	14152	Reconfigured: new=0 old=1 dropped=0 (services)
    Jun 24 10:37:50	xinetd	14152	readjusting service 6969-udp
    Jun 24 10:37:50	xinetd	14152	Swapping defaults
    Jun 24 10:37:50	xinetd	14152	Starting reconfiguration
    Jun 24 10:37:49	xinetd	14152	Reconfigured: new=0 old=1 dropped=0 (services)
    Jun 24 10:37:49	xinetd	14152	readjusting service 6969-udp
    Jun 24 10:37:49	xinetd	14152	Swapping defaults
    Jun 24 10:37:49	xinetd	14152	Starting reconfiguration
    Jun 24 10:37:48	php-fpm	74632	/rc.dyndns.update: Curl error occurred: Could not resolve host: ipv4.tunnelbroker.net
    Jun 24 10:37:47	php-fpm	65464	/rc.newwanip: Curl error occurred: Could not resolve host: freedns.afraid.org
    Jun 24 10:37:47	php-fpm	65464	/rc.newwanip: Dynamic DNS freedns (casalener.mooo.com): _checkStatus() starting.
    Jun 24 10:37:38	php-fpm	65464	/rc.newwanip: Dynamic DNS freedns (casalener.mooo.com): _update() starting.
    Jun 24 10:37:38	php-fpm	65464	/rc.newwanip: DynDns (casalener.mooo.com): Dynamic Dns: cacheIP != wan_ip. Updating. Cached IP: 80.181.221.144 WAN IP: 79.56.147.131
    Jun 24 10:37:38	php-fpm	65464	/rc.newwanip: Dynamic Dns (casalener.mooo.com): Current WAN IP: 79.56.147.131 Cached IP: 80.181.221.144
    Jun 24 10:37:38	php-fpm	65464	/rc.newwanip: Dynamic DNS freedns (casalener.mooo.com): 79.56.147.131 extracted from local system.
    Jun 24 10:37:38	php-fpm	65464	/rc.newwanip: Dynamic DNS (casalener.mooo.com): running get_failover_interface for wan. found pppoe1
    Jun 24 10:37:38	php-fpm	65464	/rc.newwanip: Dynamic DNS freedns (casalener.mooo.com): 79.56.147.131 extracted from local system.
    Jun 24 10:37:38	php-fpm	65464	/rc.newwanip: Dynamic DNS: updatedns() starting
    Jun 24 10:37:38	php-fpm	74632	/rc.dyndns.update: Curl error occurred: Could not resolve host: freedns.afraid.org
    Jun 24 10:37:38	php-fpm	74632	/rc.dyndns.update: Dynamic DNS freedns (casalener.mooo.com): _checkStatus() starting.
    Jun 24 10:37:38	check_reload_status		Reloading filter
    Jun 24 10:37:38	php-fpm	55525	/rc.newipsecdns: IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing.
    Jun 24 10:37:37	php-fpm	65464	/rc.newwanip: Curl error occurred: Could not resolve host: dynupdate.no-ip.com
    Jun 24 10:37:29	php-fpm	74632	/rc.dyndns.update: Dynamic DNS freedns (casalener.mooo.com): _update() starting.
    Jun 24 10:37:29	php-fpm	74632	/rc.dyndns.update: DynDns (casalener.mooo.com): Dynamic Dns: cacheIP != wan_ip. Updating. Cached IP: 80.181.221.144 WAN IP: 79.56.147.131
    Jun 24 10:37:29	php-fpm	74632	/rc.dyndns.update: Dynamic Dns (casalener.mooo.com): Current WAN IP: 79.56.147.131 Cached IP: 80.181.221.144
    Jun 24 10:37:29	php-fpm	74632	/rc.dyndns.update: Dynamic DNS freedns (casalener.mooo.com): 79.56.147.131 extracted from local system.
    Jun 24 10:37:29	php-fpm	74632	/rc.dyndns.update: Dynamic DNS (casalener.mooo.com): running get_failover_interface for wan. found pppoe1
    Jun 24 10:37:29	php-fpm	74632	/rc.dyndns.update: Dynamic DNS freedns (casalener.mooo.com): 79.56.147.131 extracted from local system.
    Jun 24 10:37:29	php-fpm	74632	/rc.dyndns.update: Dynamic DNS: updatedns() starting
    Jun 24 10:37:28	php-fpm	74632	/rc.dyndns.update: Curl error occurred: Could not resolve host: dynupdate.no-ip.com
    Jun 24 10:37:23	php-fpm	55525	/status_interfaces.php: ROUTING: setting IPv6 default route to 2001:470:1f12:62c::1
    Jun 24 10:37:23	kernel		gif0: link state changed to UP
    Jun 24 10:37:23	kernel		gif0: link state changed to DOWN
    Jun 24 10:37:23	php-fpm	55525	/status_interfaces.php: DEBUG: interface: opt1 interfacegw: wan gatewayip:
    Jun 24 10:37:19	check_reload_status		Reloading filter
    Jun 24 10:37:19	check_reload_status		Restarting OpenVPN tunnels/interfaces
    Jun 24 10:37:19	check_reload_status		Reloading filter
    Jun 24 10:37:19	check_reload_status		Restarting ipsec tunnels
    Jun 24 10:37:19	check_reload_status		Restarting OpenVPN tunnels/interfaces
    Jun 24 10:37:19	check_reload_status		updating dyndns HE_IPV6_TUNNELV6
    Jun 24 10:37:19	check_reload_status		Restarting ipsec tunnels
    Jun 24 10:37:19	check_reload_status		updating dyndns WAN_PPPOE
    Jun 24 10:37:16	ppp		[wan] IPV6CP: LayerFinish
    Jun 24 10:37:16	ppp		[wan] IPV6CP: state change Stopping --> Stopped
    Jun 24 10:37:16	php-fpm	65464	/rc.newwanip: Removing static route for monitor 2001:4860:4860::8888 and adding a new route through 2001:470:1f12:62c::1
    Jun 24 10:37:16	php-fpm	65464	/rc.newwanip: DEBUG: interface: wan interfacegw: wan gatewayip:
    Jun 24 10:37:15	php-fpm	74632	/rc.resolv_conf_generate: The command '/sbin/route delete -host 208.67.220.220 ' returned exit code '1', the output was 'route: writing to routing socket: No such process delete host 208.67.220.220 fib 0: not in table'
    Jun 24 10:37:15	php-fpm	74632	/rc.resolv_conf_generate: The command '/sbin/route delete -host 208.67.222.222 ' returned exit code '1', the output was 'route: writing to routing socket: No such process delete host 208.67.222.222 fib 0: not in table'
    Jun 24 10:37:15	php-fpm	74632	/rc.newwanipv6: rc.newwanipv6: No IPv6 address found for interface WAN [wan].
    Jun 24 10:37:15	php-fpm	74632	/rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe1.
    Jun 24 10:37:15	xinetd	14152	Reconfigured: new=0 old=1 dropped=0 (services)
    Jun 24 10:37:15	xinetd	14152	readjusting service 6969-udp
    Jun 24 10:37:15	xinetd	14152	Swapping defaults
    Jun 24 10:37:15	xinetd	14152	Starting reconfiguration
    Jun 24 10:37:15	php-fpm	65464	/rc.newwanip: IP has changed, killing states on former IP 79.47.194.62.
    Jun 24 10:37:15	php-fpm	65464	/rc.newwanip: ROUTING: setting IPv6 default route to 2001:470:1f12:62c::1
    Jun 24 10:37:15	kernel		gif0: link state changed to UP
    Jun 24 10:37:15	kernel		gif0: link state changed to DOWN
    Jun 24 10:37:15	php-fpm	65464	/rc.newwanip: DEBUG: interface: opt1 interfacegw: wan gatewayip:
    Jun 24 10:37:15	php-fpm	65464	/rc.newwanip: ROUTING: setting IPv6 default route to 2001:470:1f12:62c::1
    Jun 24 10:37:15	kernel		gif0: link state changed to UP
    Jun 24 10:37:15	kernel		gif0: link state changed to DOWN
    Jun 24 10:37:15	php-fpm	65464	/rc.newwanip: DEBUG: interface: opt1 interfacegw: wan gatewayip:
    Jun 24 10:37:15	php-fpm	65464	/rc.newwanip: The command '/sbin/route delete -host 208.67.220.220 ' returned exit code '1', the output was 'route: writing to routing socket: No such process delete host 208.67.220.220 fib 0: not in table'
    Jun 24 10:37:15	php-fpm	65464	/rc.newwanip: The command '/sbin/route delete -host 208.67.222.222 ' returned exit code '1', the output was 'route: writing to routing socket: No such process delete host 208.67.222.222 fib 0: not in table'
    Jun 24 10:37:15	php-fpm	65464	/rc.newwanip: rc.newwanip: on (IP address: 79.56.147.131) (interface: WAN[wan]) (real interface: pppoe1).
    Jun 24 10:37:15	php-fpm	65464	/rc.newwanip: rc.newwanip: Info: starting on pppoe1.
    Jun 24 10:37:14	check_reload_status		Rewriting resolv.conf
    Jun 24 10:37:14	ppp		[wan] IPV6CP: LayerDown
    Jun 24 10:37:14	ppp		[wan] IPV6CP: SendTerminateAck #2
    Jun 24 10:37:14	ppp		[wan] IPV6CP: state change Opened --> Stopping
    Jun 24 10:37:14	ppp		[wan] IPV6CP: rec'd Terminate Request #164 (Opened)
    Jun 24 10:37:14	check_reload_status		rc.newwanipv6 starting pppoe1
    Jun 24 10:37:14	ppp		[wan] 76d4:35ff:fe8a:b19c -> 02a0:a50f:fc86:8004
    Jun 24 10:37:14	ppp		[wan] IPV6CP: LayerUp
    Jun 24 10:37:14	ppp		[wan] IPV6CP: state change Ack-Rcvd --> Opened
    Jun 24 10:37:14	ppp		[wan] IPV6CP: SendConfigAck #163
    Jun 24 10:37:14	ppp		[wan] IPV6CP: rec'd Configure Request #163 (Ack-Rcvd)
    Jun 24 10:37:14	ppp		[wan] IFACE: Rename interface ng0 to pppoe1
    Jun 24 10:37:14	ppp		[wan] IFACE: Up event
    Jun 24 10:37:14	check_reload_status		rc.newwanip starting pppoe1
    Jun 24 10:37:13	ppp		[wan] 79.56.147.131 -> 192.168.100.1
    Jun 24 10:37:13	ppp		[wan] IPCP: LayerUp
    Jun 24 10:37:13	ppp		[wan] IPCP: state change Ack-Rcvd --> Opened
    Jun 24 10:37:13	ppp		[wan] IPADDR 192.168.100.1
    Jun 24 10:37:13	ppp		[wan] IPCP: SendConfigAck #109
    Jun 24 10:37:13	ppp		[wan] 192.168.100.1 is OK
    Jun 24 10:37:13	ppp		[wan] IPADDR 192.168.100.1
    Jun 24 10:37:13	ppp		[wan] IPCP: rec'd Configure Request #109 (Ack-Rcvd)
    Jun 24 10:37:13	ppp		[wan] IPCP: state change Req-Sent --> Ack-Rcvd
    Jun 24 10:37:13	ppp		[wan] IPADDR 79.56.147.131
    Jun 24 10:37:13	ppp		[wan] IPCP: rec'd Configure Ack #3 (Req-Sent)
    Jun 24 10:37:13	ppp		[wan] IPADDR 79.56.147.131
    Jun 24 10:37:13	ppp		[wan] IPCP: SendConfigReq #3
    Jun 24 10:37:13	ppp		[wan] 79.56.147.131 is OK
    Jun 24 10:37:13	ppp		[wan] IPADDR 79.56.147.131
    Jun 24 10:37:13	ppp		[wan] IPCP: rec'd Configure Nak #2 (Req-Sent)
    Jun 24 10:37:13	ppp		[wan] IPV6CP: state change Req-Sent --> Ack-Rcvd
    Jun 24 10:37:13	ppp		[wan] IPV6CP: rec'd Configure Ack #1 (Req-Sent)
    Jun 24 10:37:13	ppp		[wan] IPADDR 0.0.0.0
    Jun 24 10:37:13	ppp		[wan] IPCP: SendConfigReq #2
    Jun 24 10:37:13	ppp		[wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
    Jun 24 10:37:13	ppp		[wan] IPCP: rec'd Configure Reject #1 (Req-Sent)
    Jun 24 10:37:13	ppp		[wan] IPV6CP: SendConfigReq #1
    Jun 24 10:37:13	ppp		[wan] IPV6CP: state change Starting --> Req-Sent
    Jun 24 10:37:13	ppp		[wan] IPV6CP: Up event
    Jun 24 10:37:13	ppp		[wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
    Jun 24 10:37:13	ppp		[wan] IPADDR 0.0.0.0
    Jun 24 10:37:13	ppp		[wan] IPCP: SendConfigReq #1
    Jun 24 10:37:13	ppp		[wan] IPCP: state change Starting --> Req-Sent
    Jun 24 10:37:13	ppp		[wan] IPCP: Up event
    Jun 24 10:37:13	ppp		[wan] IPV6CP: LayerStart
    Jun 24 10:37:13	ppp		[wan] IPV6CP: state change Initial --> Starting
    Jun 24 10:37:13	ppp		[wan] IPV6CP: Open event
    Jun 24 10:37:13	ppp		[wan] IPCP: LayerStart
    Jun 24 10:37:13	ppp		[wan] IPCP: state change Initial --> Starting
    Jun 24 10:37:13	ppp		[wan] IPCP: Open event
    Jun 24 10:37:13	ppp		[wan] Bundle: Status update: up 1 link, total bandwidth 64000 bps
    Jun 24 10:37:13	ppp		[wan_link0] Link: Join bundle "wan"
    Jun 24 10:37:13	ppp		[wan_link0] Link: Matched action 'bundle "wan" ""'
    Jun 24 10:37:13	ppp		[wan_link0] LCP: authorization successful
    Jun 24 10:37:13	ppp		[wan_link0] PAP: rec'd ACK #1 len: 5
    Jun 24 10:37:13	ppp		[wan_link0] LCP: LayerUp
    Jun 24 10:37:13	ppp		[wan_link0] PAP: sending REQUEST #1 len: 24
    Jun 24 10:37:13	ppp		[wan_link0] PAP: using authname "aliceadsl"
    Jun 24 10:37:13	ppp		[wan_link0] LCP: auth: peer wants PAP, I want nothing
    Jun 24 10:37:13	ppp		[wan_link0] LCP: state change Ack-Sent --> Opened
    Jun 24 10:37:13	ppp		[wan_link0] MAGICNUM 0xb26eca2e
    Jun 24 10:37:13	ppp		[wan_link0] MRU 1492
    Jun 24 10:37:13	ppp		[wan_link0] PROTOCOMP
    Jun 24 10:37:13	ppp		[wan_link0] LCP: rec'd Configure Ack #1 (Ack-Sent)
    Jun 24 10:37:13	ppp		[wan_link0] LCP: state change Req-Sent --> Ack-Sent
    Jun 24 10:37:13	ppp		[wan_link0] MAGICNUM 0x5794e7e4
    Jun 24 10:37:13	ppp		[wan_link0] AUTHPROTO PAP
    Jun 24 10:37:13	ppp		[wan_link0] MRU 1492
    Jun 24 10:37:13	ppp		[wan_link0] LCP: SendConfigAck #138
    Jun 24 10:37:13	ppp		[wan_link0] MAGICNUM 0x5794e7e4
    Jun 24 10:37:13	ppp		[wan_link0] AUTHPROTO PAP
    Jun 24 10:37:13	ppp		[wan_link0] MRU 1492
    Jun 24 10:37:13	ppp		[wan_link0] LCP: rec'd Configure Request #138 (Req-Sent)
    Jun 24 10:37:13	ppp		[wan_link0] MAGICNUM 0xb26eca2e
    Jun 24 10:37:13	ppp		[wan_link0] MRU 1492
    Jun 24 10:37:13	ppp		[wan_link0] PROTOCOMP
    Jun 24 10:37:13	ppp		[wan_link0] LCP: SendConfigReq #1
    Jun 24 10:37:13	ppp		[wan_link0] LCP: state change Starting --> Req-Sent
    Jun 24 10:37:13	ppp		[wan_link0] LCP: Up event
    Jun 24 10:37:13	ppp		[wan_link0] Link: UP event
    Jun 24 10:37:13	ppp		[wan_link0] PPPoE: connection successful
    Jun 24 10:37:13	ppp		PPPoE: rec'd ACNAME "r-rm900"
    Jun 24 10:37:13	ppp		[wan_link0] PPPoE: Connecting to 'TelecomFibra'
    Jun 24 10:37:13	ppp		[wan_link0] LCP: LayerStart
    Jun 24 10:37:13	ppp		[wan_link0] LCP: state change Initial --> Starting
    Jun 24 10:37:13	ppp		[wan_link0] LCP: Open event
    Jun 24 10:37:13	kernel		ng0: changing name to 'pppoe1'
    Jun 24 10:37:13	ppp		[wan_link0] Link: OPEN event
    Jun 24 10:37:13	ppp		[wan] Bundle: Interface ng0 created
    Jun 24 10:37:13	ppp		web: web is not running
    Jun 24 10:37:13	ppp		process 65266 started, version 5.8 (root@pfSense_v2_3_1_amd64-pfSense_v2_3_1-job-13 19:20 16-May-2016)
    Jun 24 10:37:13	ppp		Multi-link PPP daemon for FreeBSD
    Jun 24 10:37:03	syslogd		kernel boot file is /boot/kernel/kernel
    
    

    Thanks in advance,



  • Thanks, that narrows it down further. get_interface_gateway is returning null in that case. Which likely means that interface's router file is empty at the time. /tmp/pppoe1_router in your case.

    What contents does /tmp/pppoe1_router have after doing that?

    Appreciate your help tracking this down.



  • Hi cmb,

    @cmb:

    Thanks, that narrows it down further. get_interface_gateway is returning null in that case. Which likely means that interface's router file is empty at the time. /tmp/pppoe1_router in your case.

    What contents does /tmp/pppoe1_router have after doing that?

    Appreciate your help tracking this down.

    It seems file doesn't exist in both code (reverted 2.2.6 and 2.3.x). The image show /tmp folder with 2.3.1_5 stock code.




  • @Marlenio:

    It seems file doesn't exist in both code (reverted 2.2.6 and 2.3.x). The image show /tmp folder with 2.3.1_5 stock code.

    Ok that's why, now just a question of why that's missing. What is your IPv6 configuration on that interface? Seems like it ends up with pppoe1_routerv6 but not the v4.



  • @cmb:

    Ok that's why, now just a question of why that's missing. What is your IPv6 configuration on that interface? Seems like it ends up with pppoe1_routerv6 but not the v4.

    I have a Hurricane Electric /64 on tunnelbroker.net (see attached image).  Yes, there's pppoe_routerv6 but ipv4 is missing.

    Thanks in advance,


    Marlenio








  • So that pppoe1_routerv6 file contains your HE gateway IP?



  • @cmb:

    So that pppoe1_routerv6 file contains your HE gateway IP?

    No, the one in pppoe1_routerv6 seems to be a link local address, like the ip in /tmp/pppoe1_ipv6 (fe80::76d4:35ff:fe8a:b19c)






  • Odd, it's like ppp-linkup is somehow not getting called or getting called missing some of its arguments.

    Last (I hope) thing to try to get to the bottom of this. In /usr/local/sbin/ppp-linkup under this line:

    DNS2_RAW="${7}"
    

    Add this line:

    logger "ppp-linkup IF: $IF | PROTOCOL: $PROTOCOL | LOCAL_IP: $LOCAL_IP | REMOTE_IP: $REMOTE_IP | AUTH_NAME: $AUTH_NAME | DNS1_RAW: $DNS1_RAW | DNS2_RAW: $DNS2_RAW"
    
    

    and replicate again. Then post the system log line that contains something like:

    root: ppp-linkup IF: pppoe1 | PROTOCOL: …



  • Hi cmb,

    @cmb:

    Odd, it's like ppp-linkup is somehow not getting called or getting called missing some of its arguments.

    Last (I hope) thing to try to get to the bottom of this. In /usr/local/sbin/ppp-linkup under this line:

    Thank you, in late afternoon i'll made the change and then post the log here.  :)



  • Hi cmb,
    here is the system log with stock source:

    
    Jun 30 18:00:27	ftp-proxy	64428	listening on 127.0.0.1 port 8021
    Jun 30 18:00:27	check_reload_status		Syncing firewall
    Jun 30 18:00:27	php-fpm	42987	[pfBlockerNG] Starting cron process.
    Jun 30 18:00:27	ftp-proxy	60589	listening on 127.0.0.1 port 8021
    Jun 30 18:00:27	check_reload_status		Reloading filter
    Jun 30 18:00:27	php-fpm	42987	/rc.start_packages: Restarting/Starting all packages.
    Jun 30 18:00:26	xinetd	13847	Reconfigured: new=0 old=1 dropped=0 (services)
    Jun 30 18:00:26	xinetd	13847	readjusting service 6969-udp
    Jun 30 18:00:26	xinetd	13847	Swapping defaults
    Jun 30 18:00:26	xinetd	13847	Starting reconfiguration
    Jun 30 18:00:25	xinetd	13847	Reconfigured: new=0 old=1 dropped=0 (services)
    Jun 30 18:00:25	xinetd	13847	readjusting service 6969-udp
    Jun 30 18:00:25	xinetd	13847	Swapping defaults
    Jun 30 18:00:25	xinetd	13847	Starting reconfiguration
    Jun 30 18:00:23	xinetd	13847	Reconfigured: new=0 old=1 dropped=0 (services)
    Jun 30 18:00:23	xinetd	13847	readjusting service 6969-udp
    Jun 30 18:00:23	xinetd	13847	Swapping defaults
    Jun 30 18:00:23	xinetd	13847	Starting reconfiguration
    Jun 30 18:00:23	check_reload_status		Reloading filter
    Jun 30 18:00:23	php-fpm	42987	/rc.newipsecdns: IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing.
    Jun 30 18:00:08	check_reload_status		Reloading filter
    Jun 30 18:00:08	php-fpm	42987	/rc.newipsecdns: IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing.
    Jun 30 17:59:52	php-fpm	42987	/rc.dyndns.update: Curl error occurred: Could not resolve host: ipv4.tunnelbroker.net
    Jun 30 17:59:42	php-fpm	42987	/rc.dyndns.update: Curl error occurred: Could not resolve host: freedns.afraid.org
    Jun 30 17:59:42	php-fpm	42987	/rc.dyndns.update: Dynamic DNS freedns (casalener.mooo.com): _checkStatus() starting.
    Jun 30 17:59:34	php-fpm	42987	/rc.dyndns.update: Dynamic DNS freedns (casalener.mooo.com): _update() starting.
    Jun 30 17:59:34	php-fpm	42987	/rc.dyndns.update: DynDns (casalener.mooo.com): Dynamic Dns: cacheIP != wan_ip. Updating. Cached IP: 82.57.156.105 WAN IP: 95.247.53.52
    Jun 30 17:59:34	php-fpm	42987	/rc.dyndns.update: Dynamic Dns (casalener.mooo.com): Current WAN IP: 95.247.53.52 Cached IP: 82.57.156.105
    Jun 30 17:59:34	php-fpm	42987	/rc.dyndns.update: Dynamic DNS freedns (casalener.mooo.com): 95.247.53.52 extracted from local system.
    Jun 30 17:59:34	php-fpm	42987	/rc.dyndns.update: Dynamic DNS (casalener.mooo.com): running get_failover_interface for wan. found pppoe1
    Jun 30 17:59:34	php-fpm	42987	/rc.dyndns.update: Dynamic DNS freedns (casalener.mooo.com): 95.247.53.52 extracted from local system.
    Jun 30 17:59:34	php-fpm	42987	/rc.dyndns.update: Dynamic DNS: updatedns() starting
    Jun 30 17:59:33	php-fpm	42987	/rc.dyndns.update: Curl error occurred: Could not resolve host: dynupdate.no-ip.com
    Jun 30 17:59:24	php-fpm	42987	/rc.resolv_conf_generate: The command '/sbin/route delete -host 208.67.220.220 ' returned exit code '1', the output was 'route: writing to routing socket: No such process delete host 208.67.220.220 fib 0: not in table'
    Jun 30 17:59:24	php-fpm	42987	/rc.resolv_conf_generate: The command '/sbin/route delete -host 208.67.222.222 ' returned exit code '1', the output was 'route: writing to routing socket: No such process delete host 208.67.222.222 fib 0: not in table'
    Jun 30 17:59:24	php-fpm	42987	/rc.newwanipv6: rc.newwanipv6: No IPv6 address found for interface WAN [wan].
    Jun 30 17:59:24	php-fpm	42987	/rc.newwanipv6: rc.newwanipv6: Info: starting on pppoe1.
    Jun 30 17:59:24	check_reload_status		Starting packages
    Jun 30 17:59:24	php-fpm	42987	/rc.newwanip: pfSense package system has detected an IP change or dynamic WAN reconnection - 82.57.156.105 -> 95.247.53.52 - Restarting packages.
    Jun 30 17:59:22	php-fpm	42987	/rc.newwanip: Creating rrd update script
    Jun 30 17:59:22	php-fpm	42987	/rc.newwanip: Resyncing OpenVPN instances for interface WAN.
    Jun 30 17:59:22	check_reload_status		Reloading filter
    Jun 30 17:59:22	php-fpm	42987	/rc.newwanip: Forcefully reloading IPsec
    Jun 30 17:59:21	php-fpm	42987	/rc.newwanip: Curl error occurred: Could not resolve host: ipv4.tunnelbroker.net
    Jun 30 17:59:11	php-fpm	42987	/rc.newwanip: Curl error occurred: Could not resolve host: freedns.afraid.org
    Jun 30 17:59:11	php-fpm	42987	/rc.newwanip: Dynamic DNS freedns (casalener.mooo.com): _checkStatus() starting.
    Jun 30 17:59:03	php-cgi		servicewatchdog_cron.php: The command '/usr/local/sbin/unbound -c /var/unbound/unbound.conf' returned exit code '1', the output was '[1467302343] unbound[3597:0] error: bind: address already in use [1467302343] unbound[3597:0] fatal error: could not open ports'
    Jun 30 17:59:02	php-fpm	42987	/rc.newwanip: Dynamic DNS freedns (casalener.mooo.com): _update() starting.
    Jun 30 17:59:02	php-fpm	42987	/rc.newwanip: DynDns (casalener.mooo.com): Dynamic Dns: cacheIP != wan_ip. Updating. Cached IP: 82.57.156.105 WAN IP: 95.247.53.52
    Jun 30 17:59:02	php-fpm	42987	/rc.newwanip: Dynamic Dns (casalener.mooo.com): Current WAN IP: 95.247.53.52 Cached IP: 82.57.156.105
    Jun 30 17:59:02	php-fpm	42987	/rc.newwanip: Dynamic DNS freedns (casalener.mooo.com): 95.247.53.52 extracted from local system.
    Jun 30 17:59:02	php-fpm	42987	/rc.newwanip: Dynamic DNS (casalener.mooo.com): running get_failover_interface for wan. found pppoe1
    Jun 30 17:59:02	php-fpm	42987	/rc.newwanip: Dynamic DNS freedns (casalener.mooo.com): 95.247.53.52 extracted from local system.
    Jun 30 17:59:02	php-fpm	42987	/rc.newwanip: Dynamic DNS: updatedns() starting
    Jun 30 17:59:01	php-fpm	42987	/rc.newwanip: Curl error occurred: Could not resolve host: dynupdate.no-ip.com
    Jun 30 17:58:04	php-cgi		servicewatchdog_cron.php: Could not send the message to mario.lener@gmail.com -- Error: could not resolve the host domain "smtp.gmail.com"
    Jun 30 17:58:00	php-cgi		servicewatchdog_cron.php: Service Watchdog detected service unbound stopped. Restarting unbound (Unbound DNS Resolver)
    Jun 30 17:57:55	check_reload_status		Reloading filter
    Jun 30 17:57:55	check_reload_status		Restarting OpenVPN tunnels/interfaces
    Jun 30 17:57:55	check_reload_status		Reloading filter
    Jun 30 17:57:55	check_reload_status		Restarting ipsec tunnels
    Jun 30 17:57:55	check_reload_status		Restarting OpenVPN tunnels/interfaces
    Jun 30 17:57:55	check_reload_status		updating dyndns HE_IPV6_TUNNELV6
    Jun 30 17:57:55	check_reload_status		Restarting ipsec tunnels
    Jun 30 17:57:55	check_reload_status		updating dyndns WAN_PPPOE
    Jun 30 17:57:52	php-fpm	42987	/rc.newwanip: Removing static route for monitor 2001:4860:4860::8888 and adding a new route through 2001:470:1f12:62c::1
    Jun 30 17:57:51	xinetd	13847	Reconfigured: new=0 old=1 dropped=0 (services)
    Jun 30 17:57:51	xinetd	13847	readjusting service 6969-udp
    Jun 30 17:57:51	xinetd	13847	Swapping defaults
    Jun 30 17:57:51	xinetd	13847	Starting reconfiguration
    Jun 30 17:57:50	php-fpm	42987	/rc.newwanip: IP has changed, killing states on former IP 82.57.156.105.
    Jun 30 17:57:50	php-fpm	42987	/rc.newwanip: ROUTING: setting IPv6 default route to 2001:470:1f12:62c::1
    Jun 30 17:57:50	kernel		gif0: link state changed to UP
    Jun 30 17:57:50	kernel		gif0: link state changed to DOWN
    Jun 30 17:57:50	kernel		gif0: link state changed to UP
    Jun 30 17:57:50	kernel		gif0: link state changed to DOWN
    Jun 30 17:57:50	php-fpm	42987	/rc.newwanip: ROUTING: setting IPv6 default route to 2001:470:1f12:62c::1
    Jun 30 17:57:50	php-fpm	42987	/rc.newwanip: The command '/sbin/route delete -host 208.67.220.220 ' returned exit code '1', the output was 'route: writing to routing socket: No such process delete host 208.67.220.220 fib 0: not in table'
    Jun 30 17:57:50	php-fpm	42987	/rc.newwanip: The command '/sbin/route delete -host 208.67.222.222 ' returned exit code '1', the output was 'route: writing to routing socket: No such process delete host 208.67.222.222 fib 0: not in table'
    Jun 30 17:57:50	php-fpm	42987	/rc.newwanip: rc.newwanip: on (IP address: 95.247.53.52) (interface: WAN[wan]) (real interface: pppoe1).
    Jun 30 17:57:50	php-fpm	42987	/rc.newwanip: rc.newwanip: Info: starting on pppoe1.
    Jun 30 17:57:49	xinetd	13847	Reconfigured: new=0 old=1 dropped=0 (services)
    Jun 30 17:57:49	xinetd	13847	readjusting service 6969-udp
    Jun 30 17:57:49	xinetd	13847	Swapping defaults
    Jun 30 17:57:49	xinetd	13847	Starting reconfiguration
    Jun 30 17:57:48	xinetd	13847	Reconfigured: new=0 old=1 dropped=0 (services)
    Jun 30 17:57:48	xinetd	13847	readjusting service 6969-udp
    Jun 30 17:57:48	xinetd	13847	Swapping defaults
    Jun 30 17:57:48	xinetd	13847	Starting reconfiguration
    Jun 30 17:57:48	kernel		gif0: link state changed to UP
    Jun 30 17:57:48	kernel		gif0: link state changed to DOWN
    Jun 30 17:57:48	php-fpm	42987	/status_interfaces.php: ROUTING: setting IPv6 default route to 2001:470:1f12:62c::1
    Jun 30 17:57:45	ppp		[wan] IPV6CP: LayerFinish
    Jun 30 17:57:45	ppp		[wan] IPV6CP: state change Stopping --> Stopped
    Jun 30 17:57:43	check_reload_status		Rewriting resolv.conf
    Jun 30 17:57:42	ppp		[wan] IPV6CP: LayerDown
    Jun 30 17:57:42	ppp		[wan] IPV6CP: SendTerminateAck #10
    Jun 30 17:57:42	ppp		[wan] IPV6CP: state change Opened --> Stopping
    Jun 30 17:57:42	ppp		[wan] IPV6CP: rec'd Terminate Request #83 (Opened)
    Jun 30 17:57:42	check_reload_status		rc.newwanipv6 starting pppoe1
    Jun 30 17:57:42	root		ppp-linkup IF: pppoe1 | PROTOCOL: inet6 | LOCAL_IP: fe80::76d4:35ff:fe8a:b19c%pppoe1 | REMOTE_IP: fe80::2a0:a50f:fc86:8004%pppoe1 | AUTH_NAME: - | DNS1_RAW: 00:00:00:00:00:00 | DNS2_RAW: -
    Jun 30 17:57:42	ppp		[wan] 76d4:35ff:fe8a:b19c -> 02a0:a50f:fc86:8004
    Jun 30 17:57:42	ppp		[wan] IPV6CP: LayerUp
    Jun 30 17:57:42	ppp		[wan] IPV6CP: state change Ack-Rcvd --> Opened
    Jun 30 17:57:42	ppp		[wan] IPV6CP: SendConfigAck #82
    Jun 30 17:57:42	ppp		[wan] IPV6CP: rec'd Configure Request #82 (Ack-Rcvd)
    Jun 30 17:57:42	ppp		[wan] IPV6CP: state change Req-Sent --> Ack-Rcvd
    Jun 30 17:57:42	ppp		[wan] IPV6CP: rec'd Configure Ack #9 (Req-Sent)
    Jun 30 17:57:42	ppp		[wan] IPV6CP: SendConfigReq #9
    Jun 30 17:57:40	ppp		[wan] IPV6CP: SendTerminateAck #8
    Jun 30 17:57:40	ppp		[wan] IPV6CP: state change Ack-Sent --> Req-Sent
    Jun 30 17:57:40	ppp		[wan] IPV6CP: rec'd Terminate Request #168 (Ack-Sent)
    Jun 30 17:57:40	ppp		[wan] IPV6CP: state change Req-Sent --> Ack-Sent
    Jun 30 17:57:40	ppp		[wan] IPV6CP: SendConfigAck #167
    Jun 30 17:57:40	ppp		[wan] IPV6CP: rec'd Configure Request #167 (Req-Sent)
    Jun 30 17:57:40	ppp		[wan] IPV6CP: SendTerminateAck #7
    Jun 30 17:57:40	ppp		[wan] IPV6CP: rec'd Terminate Request #166 (Req-Sent)
    Jun 30 17:57:40	ppp		[wan] IPV6CP: SendTerminateAck #6
    Jun 30 17:57:40	ppp		[wan] IPV6CP: state change Ack-Rcvd --> Req-Sent
    Jun 30 17:57:40	ppp		[wan] IPV6CP: rec'd Terminate Request #165 (Ack-Rcvd)
    Jun 30 17:57:40	ppp		[wan] IPV6CP: state change Req-Sent --> Ack-Rcvd
    Jun 30 17:57:40	ppp		[wan] IPV6CP: rec'd Configure Ack #5 (Req-Sent)
    Jun 30 17:57:40	ppp		[wan] IPV6CP: SendConfigReq #5
    Jun 30 17:57:38	ppp		[wan] IPV6CP: SendTerminateAck #4
    Jun 30 17:57:38	ppp		[wan] IPV6CP: state change Ack-Sent --> Req-Sent
    Jun 30 17:57:38	ppp		[wan] IPV6CP: rec'd Terminate Request #19 (Ack-Sent)
    Jun 30 17:57:38	ppp		[wan] IPV6CP: state change Req-Sent --> Ack-Sent
    Jun 30 17:57:38	ppp		[wan] IPV6CP: SendConfigAck #18
    Jun 30 17:57:38	ppp		[wan] IPV6CP: rec'd Configure Request #18 (Req-Sent)
    Jun 30 17:57:38	ppp		[wan] IFACE: Rename interface ng0 to pppoe1
    Jun 30 17:57:38	ppp		[wan] IFACE: Up event
    Jun 30 17:57:38	check_reload_status		rc.newwanip starting pppoe1
    Jun 30 17:57:38	root		ppp-linkup IF: pppoe1 | PROTOCOL: inet | LOCAL_IP: 95.247.53.52/32 | REMOTE_IP: 192.168.100.1 | AUTH_NAME: - | DNS1_RAW: | DNS2_RAW:
    Jun 30 17:57:38	ppp		[wan] 95.247.53.52 -> 192.168.100.1
    Jun 30 17:57:38	ppp		[wan] IPCP: LayerUp
    Jun 30 17:57:38	ppp		[wan] IPCP: state change Ack-Rcvd --> Opened
    Jun 30 17:57:38	ppp		[wan] IPADDR 192.168.100.1
    Jun 30 17:57:38	ppp		[wan] IPCP: SendConfigAck #175
    Jun 30 17:57:38	ppp		[wan] 192.168.100.1 is OK
    Jun 30 17:57:38	ppp		[wan] IPADDR 192.168.100.1
    Jun 30 17:57:38	ppp		[wan] IPCP: rec'd Configure Request #175 (Ack-Rcvd)
    Jun 30 17:57:38	ppp		[wan] IPV6CP: SendTerminateAck #3
    Jun 30 17:57:38	ppp		[wan] IPV6CP: rec'd Terminate Request #17 (Req-Sent)
    Jun 30 17:57:38	ppp		[wan] IPV6CP: SendTerminateAck #2
    Jun 30 17:57:38	ppp		[wan] IPV6CP: state change Ack-Rcvd --> Req-Sent
    Jun 30 17:57:38	ppp		[wan] IPV6CP: rec'd Terminate Request #16 (Ack-Rcvd)
    Jun 30 17:57:38	ppp		[wan] IPCP: state change Req-Sent --> Ack-Rcvd
    Jun 30 17:57:38	ppp		[wan] IPADDR 95.247.53.52
    Jun 30 17:57:38	ppp		[wan] IPCP: rec'd Configure Ack #3 (Req-Sent)
    Jun 30 17:57:38	ppp		[wan] IPADDR 95.247.53.52
    Jun 30 17:57:38	ppp		[wan] IPCP: SendConfigReq #3
    Jun 30 17:57:38	ppp		[wan] 95.247.53.52 is OK
    Jun 30 17:57:38	ppp		[wan] IPADDR 95.247.53.52
    Jun 30 17:57:38	ppp		[wan] IPCP: rec'd Configure Nak #2 (Req-Sent)
    Jun 30 17:57:38	ppp		[wan] IPV6CP: state change Req-Sent --> Ack-Rcvd
    Jun 30 17:57:38	ppp		[wan] IPV6CP: rec'd Configure Ack #1 (Req-Sent)
    Jun 30 17:57:38	ppp		[wan] IPADDR 0.0.0.0
    Jun 30 17:57:38	ppp		[wan] IPCP: SendConfigReq #2
    Jun 30 17:57:38	ppp		[wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
    Jun 30 17:57:38	ppp		[wan] IPCP: rec'd Configure Reject #1 (Req-Sent)
    Jun 30 17:57:38	ppp		[wan] IPV6CP: SendConfigReq #1
    Jun 30 17:57:38	ppp		[wan] IPV6CP: state change Starting --> Req-Sent
    Jun 30 17:57:38	ppp		[wan] IPV6CP: Up event
    Jun 30 17:57:38	ppp		[wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
    Jun 30 17:57:38	ppp		[wan] IPADDR 0.0.0.0
    Jun 30 17:57:38	ppp		[wan] IPCP: SendConfigReq #1
    Jun 30 17:57:38	ppp		[wan] IPCP: state change Starting --> Req-Sent
    Jun 30 17:57:38	ppp		[wan] IPCP: Up event
    Jun 30 17:57:38	ppp		[wan] IPV6CP: LayerStart
    Jun 30 17:57:38	ppp		[wan] IPV6CP: state change Initial --> Starting
    Jun 30 17:57:38	ppp		[wan] IPV6CP: Open event
    Jun 30 17:57:38	ppp		[wan] IPCP: LayerStart
    Jun 30 17:57:38	ppp		[wan] IPCP: state change Initial --> Starting
    Jun 30 17:57:38	ppp		[wan] IPCP: Open event
    Jun 30 17:57:38	ppp		[wan] Bundle: Status update: up 1 link, total bandwidth 64000 bps
    Jun 30 17:57:38	ppp		[wan_link0] Link: Join bundle "wan"
    Jun 30 17:57:38	ppp		[wan_link0] Link: Matched action 'bundle "wan" ""'
    Jun 30 17:57:38	ppp		[wan_link0] LCP: authorization successful
    Jun 30 17:57:38	ppp		[wan_link0] PAP: rec'd ACK #1 len: 5
    Jun 30 17:57:38	ppp		[wan_link0] LCP: LayerUp
    Jun 30 17:57:38	ppp		[wan_link0] PAP: sending REQUEST #1 len: 24
    Jun 30 17:57:38	ppp		[wan_link0] PAP: using authname "aliceadsl"
    Jun 30 17:57:38	ppp		[wan_link0] LCP: auth: peer wants PAP, I want nothing
    Jun 30 17:57:38	ppp		[wan_link0] LCP: state change Ack-Sent --> Opened
    Jun 30 17:57:38	ppp		[wan_link0] MAGICNUM 0x959498d9
    Jun 30 17:57:38	ppp		[wan_link0] MRU 1492
    Jun 30 17:57:38	ppp		[wan_link0] PROTOCOMP
    Jun 30 17:57:38	ppp		[wan_link0] LCP: rec'd Configure Ack #1 (Ack-Sent)
    Jun 30 17:57:38	ppp		[wan_link0] LCP: state change Req-Sent --> Ack-Sent
    Jun 30 17:57:38	ppp		[wan_link0] MAGICNUM 0x484e41c9
    Jun 30 17:57:38	ppp		[wan_link0] AUTHPROTO PAP
    Jun 30 17:57:38	ppp		[wan_link0] MRU 1492
    Jun 30 17:57:38	ppp		[wan_link0] LCP: SendConfigAck #51
    Jun 30 17:57:38	ppp		[wan_link0] MAGICNUM 0x484e41c9
    Jun 30 17:57:38	ppp		[wan_link0] AUTHPROTO PAP
    Jun 30 17:57:38	ppp		[wan_link0] MRU 1492
    Jun 30 17:57:38	ppp		[wan_link0] LCP: rec'd Configure Request #51 (Req-Sent)
    Jun 30 17:57:38	ppp		[wan_link0] MAGICNUM 0x959498d9
    Jun 30 17:57:38	ppp		[wan_link0] MRU 1492
    Jun 30 17:57:38	ppp		[wan_link0] PROTOCOMP
    Jun 30 17:57:38	ppp		[wan_link0] LCP: SendConfigReq #1
    Jun 30 17:57:38	ppp		[wan_link0] LCP: state change Starting --> Req-Sent
    Jun 30 17:57:38	ppp		[wan_link0] LCP: Up event
    Jun 30 17:57:38	ppp		[wan_link0] Link: UP event
    Jun 30 17:57:38	ppp		[wan_link0] PPPoE: connection successful
    Jun 30 17:57:38	ppp		PPPoE: rec'd ACNAME "r-rm900"
    Jun 30 17:57:38	ppp		[wan_link0] PPPoE: Connecting to 'TelecomFibra'
    Jun 30 17:57:38	ppp		[wan_link0] LCP: LayerStart
    Jun 30 17:57:38	ppp		[wan_link0] LCP: state change Initial --> Starting
    Jun 30 17:57:38	ppp		[wan_link0] LCP: Open event
    Jun 30 17:57:38	kernel		ng0: changing name to 'pppoe1'
    Jun 30 17:57:38	ppp		[wan_link0] Link: OPEN event
    Jun 30 17:57:38	ppp		[wan] Bundle: Interface ng0 created
    Jun 30 17:57:38	ppp		web: web is not running
    Jun 30 17:57:38	ppp		process 38583 started, version 5.8 (root@pfSense_v2_3_1_amd64-pfSense_v2_3_1-job-13 19:20 16-May-2016)
    Jun 30 17:57:38	ppp		Multi-link PPP daemon for FreeBSD
    Jun 30 17:57:37	xinetd	13847	Reconfigured: new=0 old=1 dropped=0 (services)
    Jun 30 17:57:37	xinetd	13847	readjusting service 6969-udp
    Jun 30 17:57:37	xinetd	13847	Swapping defaults
    Jun 30 17:57:37	xinetd	13847	Starting reconfiguration
    Jun 30 17:57:36	php-fpm	42987	/rc.newipsecdns: IPsec ERROR: Could not find phase 1 source for connection Soflab MI (FW-MI01 Endpoint). Omitting from configuration file.
    Jun 30 17:57:36	php-fpm	42987	/rc.newipsecdns: IPsec ERROR: Could not find phase 1 source for connection Soflab RM (FW-LW01 Endpoint). Omitting from configuration file.
    Jun 30 17:57:36	check_reload_status		Reloading filter
    Jun 30 17:57:36	php-fpm	42987	/rc.newipsecdns: IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing.
    Jun 30 17:57:20	xinetd	13847	Reconfigured: new=0 old=1 dropped=0 (services)
    Jun 30 17:57:20	xinetd	13847	readjusting service 6969-udp
    Jun 30 17:57:20	xinetd	13847	Swapping defaults
    Jun 30 17:57:20	xinetd	13847	Starting reconfiguration
    Jun 30 17:57:20	php-fpm	42987	/rc.newipsecdns: IPsec ERROR: Could not find phase 1 source for connection Soflab MI (FW-MI01 Endpoint). Omitting from configuration file.
    Jun 30 17:57:20	php-fpm	42987	/rc.newipsecdns: IPsec ERROR: Could not find phase 1 source for connection Soflab RM (FW-LW01 Endpoint). Omitting from configuration file.
    Jun 30 17:57:20	check_reload_status		Reloading filter
    Jun 30 17:57:20	php-fpm	42987	/rc.newipsecdns: IPSEC: One or more IPsec tunnel endpoints has changed its IP. Refreshing.
    Jun 30 17:57:04	php-fpm	42987	/rc.dyndns.update: Dynamic DNS (310435) There was an error trying to determine the public IP for interface - wan (pppoe1 ).
    Jun 30 17:57:03	php-fpm	42987	/rc.dyndns.update: Dynamic DNS (casalener.mooo.com) There was an error trying to determine the public IP for interface - wan (pppoe1 ).
    Jun 30 17:57:03	php-fpm	42987	/rc.dyndns.update: Dynamic DNS (casalener.mooo.com): running get_failover_interface for wan. found pppoe1
    Jun 30 17:57:03	php-fpm	42987	/rc.dyndns.update: Dynamic DNS: updatedns() starting
    Jun 30 17:57:02	php-fpm	42987	/rc.dyndns.update: Dynamic DNS (casalener.no-ip.info) There was an error trying to determine the public IP for interface - wan (pppoe1 ).
    Jun 30 17:57:01	check_reload_status		Reloading filter
    Jun 30 17:57:01	check_reload_status		Restarting OpenVPN tunnels/interfaces
    Jun 30 17:57:01	check_reload_status		Restarting ipsec tunnels
    Jun 30 17:57:01	check_reload_status		updating dyndns HE_IPV6_TUNNELV6
    Jun 30 17:57:00	check_reload_status		Reloading filter
    Jun 30 17:57:00	check_reload_status		Restarting OpenVPN tunnels/interfaces
    Jun 30 17:57:00	check_reload_status		Restarting ipsec tunnels
    Jun 30 17:57:00	check_reload_status		updating dyndns WAN_PPPOE
    Jun 30 17:57:00	syslogd		kernel boot file is /boot/kernel/kernel
    
    

    Thanks in advance,



  • I have similar problem on one pfSense box after upgrade from 2.2 to 2.3, but my WAN interface is L2TP, not PPPoE.

    • No default gateway after reboot;
    • /tmp/l2tp1_defaultgw is empty after reboot;
    • Edit+save of WAN interface or WAN gateway restores default route.


  • @Taras:

    I have similar problem on one pfSense box after upgrade from 2.2 to 2.3, but my WAN interface is L2TP, not PPPoE.

    • No default gateway after reboot;
    • /tmp/l2tp1_defaultgw is empty after reboot;
    • Edit+save of WAN interface or WAN gateway restores default route.

    Have you try the mod to the code i post?