Automatic dis-reconnect via PPPOE runs wrong

[_igor_]

Due to the strange gateway-things i notice since some time, i found out that the disappearing gateway (WAN) has to do with the reconnect of PPPOE:

Here the log beginning with the reconnect (System-log):

Sep 10 06:00:10 apinger: ALARM: WAN(195.14.226.7) *** down ***
Sep 10 06:00:06 dnsmasq[30955]: using nameserver 217.79.186.148#53
Sep 10 06:00:06 dnsmasq[30955]: using nameserver 213.73.91.35#53
Sep 10 06:00:06 dnsmasq[30955]: reading /etc/resolv.conf
Sep 10 06:00:05 check_reload_status: Rewriting resolv.conf
Sep 10 06:00:03 check_reload_status: configuring interface wan
Sep 10 06:00:01 php: : The command 'route add -host 213.73.91.35 195.14.226.7' returned exit code '1', the output was 'route: writing to routing socket: Network is unreachable add host 213.73.91.35: gateway 195.14.226.7: Network is unreachable'
Sep 10 06:00:01 php: : The command 'route add -host 217.79.186.148 195.14.226.7' returned exit code '1', the output was 'route: writing to routing socket: Network is unreachable add host 217.79.186.148: gateway 195.14.226.7: Network is unreachable'
Sep 10 06:00:01 check_reload_status: Rewriting resolv.conf

Here the corresponding PPP-log:

Sep 10 06:00:04 ppp: Multi-link PPP daemon for FreeBSD
Sep 10 06:00:03 ppp: process 56097 terminated
Sep 10 06:00:03 ppp: [wan_link0] Link: Shutdown
Sep 10 06:00:03 ppp: [wan] Bundle: Shutdown
Sep 10 06:00:01 ppp: [wan_link0] LCP: state change Closed –> Initial
Sep 10 06:00:01 ppp: [wan_link0] LCP: Down event
Sep 10 06:00:01 ppp: [wan_link0] Link: DOWN event
Sep 10 06:00:01 ppp: [wan_link0] LCP: LayerFinish
Sep 10 06:00:01 ppp: [wan_link0] LCP: state change Closing –> Closed
Sep 10 06:00:01 ppp: [wan_link0] LCP: rec'd Terminate Ack #2 (Closing)
Sep 10 06:00:01 ppp: [wan_link0] LCP: LayerDown
Sep 10 06:00:01 ppp: [wan_link0] LCP: SendTerminateReq #2
Sep 10 06:00:01 ppp: [wan] IPCP: state change Closed –> Initial
Sep 10 06:00:01 ppp: [wan] IPCP: Down event
Sep 10 06:00:01 ppp: [wan] IPCP: Close event
Sep 10 06:00:01 ppp: [wan] Bundle: Status update: up 0 links, total bandwidth 9600 bps
Sep 10 06:00:01 ppp: [wan_link0] Link: Leave bundle "wan"
Sep 10 06:00:01 ppp: [wan_link0] LCP: state change Opened –> Closing
Sep 10 06:00:01 ppp: [wan_link0] LCP: Close event
Sep 10 06:00:01 ppp: [wan_link0] Link: CLOSE event
Sep 10 06:00:01 ppp: [wan] Bundle: closing link "wan_link0"…
Sep 10 06:00:01 ppp: [wan] Bundle: No NCPs left. Closing links…
Sep 10 06:00:01 ppp: [wan] IPCP: LayerFinish
Sep 10 06:00:01 ppp: [wan] IPCP: state change Closing –> Closed
Sep 10 06:00:01 ppp: [wan] IPCP: rec'd Terminate Ack #4 (Closing)
Sep 10 06:00:01 ppp: [wan] IFACE: Down event
Sep 10 06:00:01 ppp: [wan] IPCP: LayerDown
Sep 10 06:00:01 ppp: [wan] IPCP: SendTerminateReq #4
Sep 10 06:00:01 ppp: [wan] IPCP: state change Opened –> Closing
Sep 10 06:00:01 ppp: [wan] IPCP: Close event
Sep 10 06:00:01 ppp: [wan] IFACE: Close event
Sep 10 06:00:01 ppp: caught fatal signal term

As you can see, the new routing-script runs before any connect succeded! Thats not the way it should be i think.

5 secs after the failing routing-command PPP was up, died and connected newly.
Finally the connect was here:

Sep 10 06:00:09 ppp: [wan] IFACE: Up event

[jimp]

What date snapshot are you using?

iirc there were some updates to the ppp-linkup/ppp-linkdown script yesterday that I haven't had time to try on mine, but those should only run after a connection has been made, not before.

[_igor_]

I've tested with snap 2.0-BETA4 (i386) built on Sat Sep 11 06:51:55 EDT 2010 and the problem is not completely gone. The routing-script-error is gone, but apinger still fails and with this gateway is shown as dead.

System-log:
Sep 12 06:00:21 check_reload_status: reloading filter
Sep 12 06:00:11 apinger: ALARM: WAN(195.14.226.7) *** down ***
Sep 12 06:00:04 dnsmasq[28666]: using nameserver 217.79.186.148#53
Sep 12 06:00:04 dnsmasq[28666]: using nameserver 213.73.91.35#53
Sep 12 06:00:04 dnsmasq[28666]: reading /etc/resolv.conf
Sep 12 06:00:03 check_reload_status: configuring interface wan
Sep 12 06:00:01 check_reload_status: Rewriting resolv.conf

PPP-Log:
Sep 12 06:00:07 ppp: [wan] IFACE: Up event

[_igor_]

I updated today (2.0-BETA4 (i386) built on Sat Sep 11 15:41:29 EDT 2010) and can say, its failing still completely!

PPP was not up after reboot which comes after install and all scripts went on.

When PPP was up finally nothing more happened in the system-log:

PPP-log:
Sep 12 12:04:19 ppp: [wan] IFACE: Up event
Sep 12 12:04:19 ppp: [wan] 87.79.y.y -> 195.14.x.x

System-log:
Sep 12 12:01:59 php: : Resyncing configuration for all packages. –> at 12:09 this is still the last entry.
Sep 12 12:01:58 php: : Creating rrd update script
Sep 12 12:01:58 last message repeated 2 times
Sep 12 12:01:58 php: : Could not find gateway for interface(wan).
Sep 12 12:01:56 php: : phpDynDNS: (Unknown Response)