Pfsense / DSL / pppoe on WAN loose connection

gbosco · Jan 7, 2007, 10:28 AM

pfSense 1.0.1-last-CVS

ADSL2+ Dlink DSL-320T modem, configured in bridge modem (RFC1483 IP LLC), connected to my Pfsense WAN.

Pfsense is configured to establish a PPPoE connection.

ISP, Telecom Italia, "Alice" adsl (consumer level).

Problem: From time to time (sometimes, even quite often every 5 or 20 minutes), my pfSense looses the PPPoE connection, and reestablishes
it again. The connection isn´t unstable if I connected the modem directly to a computer - which makes me exclude that the ISP is the problem.

Here is the log, from the "system" section:

long - 200 lines

Jan 7 10:36:38 dnsmasq[9534]: using nameserver 85.37.17.43#53
Jan 7 10:36:38 dnsmasq[9534]: reading /etc/resolv.conf
Jan 7 10:33:31 php: : phpDynDNS: (Success) IP Address Changed Successfully!
Jan 7 10:33:31 php: : phpDynDNS: updating cache file /cf/conf/dyndns.cache: 87.4.26.142
Jan 7 10:33:31 php: : DynDns: Current Service: dyndns-custom
Jan 7 10:33:31 php: : DynDns: DynDns _checkStatus() starting.
Jan 7 10:33:30 php: : DynDns: DynDns _update() starting.
Jan 7 10:33:30 php: : DynDns: cacheIP != wan_ip. Updating.
Jan 7 10:33:30 php: : DynDns: Cached IP: 87.4.244.209
Jan 7 10:33:30 php: : DynDns: Current WAN IP: 87.4.26.142
Jan 7 10:33:30 php: : DynDns: _detectChange() starting.
Jan 7 10:33:30 php: : DynDns: updatedns() starting
Jan 7 10:33:30 php: : DynDns: Running updatedns()
Jan 7 10:33:27 check_reload_status: updating dyndns
Jan 7 10:33:20 check_reload_status: reloading filter
Jan 7 10:33:20 php: : Configuring slbd
Jan 7 10:33:20 php: : Resyncing configuration for all packages.
Jan 7 10:33:16 php: : Creating rrd update script
Jan 7 10:33:16 php: : Informational: DHClient spawned /etc/rc.newwanip and the new ip is wan - 87.4.26.142.
Jan 7 10:33:14 php: : Informational: rc.newwanip is starting.
Jan 7 10:33:12 check_reload_status: rc.newwanip starting
Jan 7 10:33:10 mpd: 87.4.26.142 -> 217.141.109.24
Jan 7 10:33:10 mpd: PRIDNS 85.37.17.43
Jan 7 10:33:10 mpd: IPADDR 87.4.26.142
Jan 7 10:33:10 mpd: PRIDNS 85.37.17.43
Jan 7 10:33:10 mpd: IPADDR 87.4.26.142
Jan 7 10:33:10 mpd: PRIDNS 85.37.17.43
Jan 7 10:33:10 mpd: 87.4.26.142 is OK
Jan 7 10:33:10 mpd: IPADDR 87.4.26.142
Jan 7 10:33:10 mpd: PRIDNS 0.0.0.0
Jan 7 10:33:10 mpd: IPADDR 0.0.0.0
Jan 7 10:33:10 mpd: COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Jan 7 10:33:10 mpd: IPADDR 217.141.109.24
Jan 7 10:33:10 mpd: 217.141.109.24 is OK
Jan 7 10:33:10 mpd: IPADDR 217.141.109.24
Jan 7 10:33:10 mpd: PRIDNS 0.0.0.0
Jan 7 10:33:10 mpd: COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Jan 7 10:33:10 mpd: IPADDR 0.0.0.0
Jan 7 10:33:10 mpd: MAGICNUM fbf972ce
Jan 7 10:33:10 mpd: MRU 1492
Jan 7 10:33:10 mpd: MAGICNUM 3a62db88
Jan 7 10:33:10 mpd: AUTHPROTO PAP
Jan 7 10:33:10 mpd: MRU 1492
Jan 7 10:33:10 mpd: MAGICNUM 3a62db88
Jan 7 10:33:10 mpd: AUTHPROTO PAP
Jan 7 10:33:10 mpd: MRU 1492
Jan 7 10:33:09 mpd: MAGICNUM fbf972ce
Jan 7 10:33:09 mpd: MRU 1492
Jan 7 10:31:41 php: : phpDynDNS: (Success) IP Address Changed Successfully!
Jan 7 10:31:41 php: : phpDynDNS: updating cache file /cf/conf/dyndns.cache: 87.4.244.209
Jan 7 10:31:41 php: : DynDns: Current Service: dyndns-custom
Jan 7 10:31:41 php: : DynDns: DynDns _checkStatus() starting.
Jan 7 10:31:39 php: : DynDns: DynDns _update() starting.
Jan 7 10:31:39 php: : DynDns: cacheIP != wan_ip. Updating.
Jan 7 10:31:39 php: : DynDns: Cached IP: 87.8.245.83
Jan 7 10:31:39 php: : DynDns: Current WAN IP: 87.4.244.209
Jan 7 10:31:39 php: : DynDns: _detectChange() starting.
Jan 7 10:31:39 php: : DynDns: updatedns() starting
Jan 7 10:31:38 php: : DynDns: Running updatedns()
Jan 7 10:31:36 check_reload_status: updating dyndns
Jan 7 10:31:29 check_reload_status: reloading filter
Jan 7 10:31:29 php: : Configuring slbd
Jan 7 10:31:29 php: : Resyncing configuration for all packages.
Jan 7 10:31:25 php: : Creating rrd update script
Jan 7 10:31:25 php: : Informational: DHClient spawned /etc/rc.newwanip and the new ip is wan - 87.4.244.209.
Jan 7 10:31:22 php: : Informational: rc.newwanip is starting.
Jan 7 10:31:21 check_reload_status: rc.newwanip starting
Jan 7 10:31:17 mpd: 87.4.244.209 -> 217.141.109.24
Jan 7 10:31:17 mpd: PRIDNS 85.37.17.43
Jan 7 10:31:17 mpd: IPADDR 87.4.244.209
Jan 7 10:31:17 mpd: PRIDNS 85.37.17.43
Jan 7 10:31:17 mpd: IPADDR 87.4.244.209
Jan 7 10:31:17 mpd: PRIDNS 85.37.17.43
Jan 7 10:31:17 mpd: 87.4.244.209 is OK
Jan 7 10:31:17 mpd: IPADDR 87.4.244.209
Jan 7 10:31:17 mpd: PRIDNS 0.0.0.0
Jan 7 10:31:17 mpd: IPADDR 0.0.0.0
Jan 7 10:31:17 mpd: COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Jan 7 10:31:17 mpd: IPADDR 217.141.109.24
Jan 7 10:31:17 mpd: 217.141.109.24 is OK
Jan 7 10:31:17 mpd: IPADDR 217.141.109.24
Jan 7 10:31:17 mpd: PRIDNS 0.0.0.0
Jan 7 10:31:17 mpd: COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Jan 7 10:31:17 mpd: IPADDR 0.0.0.0
Jan 7 10:31:16 mpd: MAGICNUM f70a96b0
Jan 7 10:31:16 mpd: MRU 1492
Jan 7 10:31:16 mpd: MAGICNUM 7f43214f
Jan 7 10:31:16 mpd: AUTHPROTO PAP
Jan 7 10:31:16 mpd: MRU 1492
Jan 7 10:31:16 mpd: MAGICNUM 7f43214f
Jan 7 10:31:16 mpd: AUTHPROTO PAP
Jan 7 10:31:16 mpd: MRU 1492
Jan 7 10:31:16 mpd: MAGICNUM f70a96b0
Jan 7 10:31:16 mpd: MRU 1492
Jan 7 10:03:26 php: : phpDynDNS: (Unknown Response)
Jan 7 10:03:26 php: : phpDynDNS: PAYLOAD:
Jan 7 10:03:26 php: : DynDns: Current Service: dyndns-custom
Jan 7 10:03:26 php: : DynDns: DynDns _checkStatus() starting.
Jan 7 10:03:26 php: : Curl errror occured: Couldn't resolve host 'members.dyndns.org'
Jan 7 10:02:40 php: : DynDns: DynDns _update() starting.
Jan 7 10:02:40 php: : DynDns: cacheIP != wan_ip. Updating.
Jan 7 10:02:40 php: : DynDns: Cached IP: 87.8.245.83
Jan 7 10:02:40 php: : DynDns: Current WAN IP: 87.9.245.57
Jan 7 10:02:40 php: : DynDns: _detectChange() starting.
Jan 7 10:02:40 php: : DynDns: updatedns() starting
Jan 7 10:02:40 php: : DynDns: Running updatedns()
Jan 7 10:02:38 check_reload_status: updating dyndns
Jan 7 10:02:31 check_reload_status: reloading filter
Jan 7 10:02:31 php: : Configuring slbd
Jan 7 10:02:31 php: : Resyncing configuration for all packages.
Jan 7 10:02:28 dnsmasq[9534]: using nameserver 85.37.17.43#53
Jan 7 10:02:28 dnsmasq[9534]: reading /etc/resolv.conf
Jan 7 10:02:27 php: : Creating rrd update script
Jan 7 10:02:27 php: : Informational: DHClient spawned /etc/rc.newwanip and the new ip is wan - 87.9.245.57.
Jan 7 10:02:25 php: : Informational: rc.newwanip is starting.
Jan 7 10:02:23 check_reload_status: rc.newwanip starting
Jan 7 10:02:20 mpd: 87.9.245.57 -> 217.141.109.24
Jan 7 10:02:20 mpd: PRIDNS 85.37.17.43
Jan 7 10:02:20 mpd: IPADDR 87.9.245.57
Jan 7 10:02:20 mpd: PRIDNS 85.37.17.43
Jan 7 10:02:20 mpd: IPADDR 87.9.245.57
Jan 7 10:02:20 mpd: PRIDNS 85.37.17.43
Jan 7 10:02:20 mpd: 87.9.245.57 is OK
Jan 7 10:02:20 mpd: IPADDR 87.9.245.57
Jan 7 10:02:20 mpd: PRIDNS 0.0.0.0
Jan 7 10:02:20 mpd: IPADDR 0.0.0.0
Jan 7 10:02:20 mpd: COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Jan 7 10:02:20 mpd: IPADDR 217.141.109.24
Jan 7 10:02:20 mpd: 217.141.109.24 is OK
Jan 7 10:02:20 mpd: IPADDR 217.141.109.24
Jan 7 10:02:20 mpd: PRIDNS 0.0.0.0
Jan 7 10:02:20 mpd: COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Jan 7 10:02:20 mpd: IPADDR 0.0.0.0
Jan 7 10:02:20 mpd: MAGICNUM efeab556
Jan 7 10:02:20 mpd: MRU 1492
Jan 7 10:02:20 mpd: MAGICNUM 58814b9d
Jan 7 10:02:20 mpd: AUTHPROTO PAP
Jan 7 10:02:20 mpd: MRU 1492
Jan 7 10:02:20 mpd: MAGICNUM 58814b9d
Jan 7 10:02:20 mpd: AUTHPROTO PAP
Jan 7 10:02:20 mpd: MRU 1492
Jan 7 10:02:20 mpd: MAGICNUM efeab556
Jan 7 10:02:20 mpd: MRU 1492
Jan 7 09:56:30 dnsmasq[9534]: using nameserver 85.37.17.43#53
Jan 7 09:56:30 dnsmasq[9534]: reading /etc/resolv.conf
Jan 7 09:50:51 php: : phpDynDNS: (Success) IP Address Changed Successfully!
Jan 7 09:50:51 php: : phpDynDNS: updating cache file /cf/conf/dyndns.cache: 87.8.245.83
Jan 7 09:50:51 php: : DynDns: Current Service: dyndns-custom
Jan 7 09:50:51 php: : DynDns: DynDns _checkStatus() starting.
Jan 7 09:50:50 php: : DynDns: DynDns _update() starting.
Jan 7 09:50:50 php: : DynDns: cacheIP != wan_ip. Updating.
Jan 7 09:50:50 php: : DynDns: Cached IP: 87.8.245.192
Jan 7 09:50:50 php: : DynDns: Current WAN IP: 87.8.245.83
Jan 7 09:50:50 php: : DynDns: _detectChange() starting.
Jan 7 09:50:50 php: : DynDns: updatedns() starting
Jan 7 09:50:50 php: : DynDns: Running updatedns()
Jan 7 09:50:47 check_reload_status: updating dyndns
Jan 7 09:50:40 check_reload_status: reloading filter
Jan 7 09:50:40 php: : Configuring slbd
Jan 7 09:50:40 php: : Resyncing configuration for all packages.
Jan 7 09:50:36 php: : Creating rrd update script
Jan 7 09:50:36 php: : Informational: DHClient spawned /etc/rc.newwanip and the new ip is wan - 87.8.245.83.
Jan 7 09:50:33 php: : Informational: rc.newwanip is starting.
Jan 7 09:50:31 check_reload_status: rc.newwanip starting
Jan 7 09:50:28 mpd: 87.8.245.83 -> 217.141.109.24
Jan 7 09:50:28 mpd: IPADDR 217.141.109.24
Jan 7 09:50:28 mpd: 217.141.109.24 is OK
Jan 7 09:50:28 mpd: IPADDR 217.141.109.24
Jan 7 09:50:27 mpd: PRIDNS 85.37.17.43
Jan 7 09:50:27 mpd: IPADDR 87.8.245.83
Jan 7 09:50:27 mpd: PRIDNS 85.37.17.43
Jan 7 09:50:27 mpd: IPADDR 87.8.245.83
Jan 7 09:50:25 mpd: PRIDNS 85.37.17.43
Jan 7 09:50:25 mpd: IPADDR 87.8.245.83
Jan 7 09:50:25 mpd: PRIDNS 85.37.17.43
Jan 7 09:50:25 mpd: 87.8.245.83 is OK
Jan 7 09:50:25 mpd: IPADDR 87.8.245.83
Jan 7 09:50:25 mpd: PRIDNS 0.0.0.0
Jan 7 09:50:25 mpd: IPADDR 0.0.0.0
Jan 7 09:50:25 mpd: COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Jan 7 09:50:25 mpd: PRIDNS 0.0.0.0
Jan 7 09:50:25 mpd: COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
Jan 7 09:50:25 mpd: IPADDR 0.0.0.0
Jan 7 09:50:24 mpd: MAGICNUM fa576fce
Jan 7 09:50:24 mpd: MRU 1492
Jan 7 09:50:24 mpd: MAGICNUM 113f7b85
Jan 7 09:50:24 mpd: AUTHPROTO PAP
Jan 7 09:50:24 mpd: MRU 1492
Jan 7 09:50:24 mpd: MAGICNUM 113f7b85
Jan 7 09:50:24 mpd: AUTHPROTO PAP
Jan 7 09:50:24 mpd: MRU 1492
Jan 7 09:50:24 mpd: MAGICNUM fa576fce
Jan 7 09:50:24 mpd: MRU 1492
Jan 7 09:50:23 mpd: MAGICNUM 6dcb24e4
Jan 7 09:50:23 mpd: AUTHPROTO PAP
Jan 7 09:50:23 mpd: MRU 1492
Jan 7 09:50:23 mpd: MAGICNUM 6dcb24e4
Jan 7 09:50:23 mpd: AUTHPROTO PAP
Jan 7 09:50:23 mpd: MRU 1492
Jan 7 09:50:22 mpd: MAGICNUM fa576fce

** end 200 lines **

/gbosco

yoda715 · Jan 8, 2007, 12:16 AM

Make sure you have the 'Dial on Demand' option unchecked under Interfaces>WAN, PPPoE configuration.

gbosco · Jan 8, 2007, 4:37 PM

"Dial on Demand" was already unchecked.

I digged more into the logs, and found out that:

** little selected snippet **

Jan 8 10:24:09 6senso mpd: [pppoe] LCP: no reply to 1 echo request(s)
Jan 8 10:24:19 6senso mpd: [pppoe] LCP: no reply to 2 echo request(s)
Jan 8 10:25:29 6senso mpd: [pppoe] LCP: no reply to 1 echo request(s)
Jan 8 10:25:39 6senso mpd: [pppoe] LCP: no reply to 2 echo request(s)
Jan 8 10:25:49 6senso mpd: [pppoe] LCP: no reply to 3 echo request(s)
Jan 8 10:25:59 6senso mpd: [pppoe] LCP: no reply to 4 echo request(s)
Jan 8 10:26:09 6senso mpd: [pppoe] LCP: no reply to 5 echo request(s)
Jan 8 10:26:09 6senso mpd: [pppoe] LCP: peer not responding to echo requests
Jan 8 10:26:09 6senso mpd: [pppoe] LCP: LayerFinish

** end selected snippet **

from time to time MPD, sends out this LCP echo packets, and for some reason - does not receive any answer from my ISP. MPD then - decide to bring
down my PPPoE connection, to take it up again after few seconds. This changes my public IP, and disrupts temporarily connectivity.

I´m evaluating whether to disable LCP requests from MPD.

What could that be the effects, of such a course of action?

/gbosco

hoba · Jan 8, 2007, 9:05 PM

Watch your modem. If you have a bad line it might go to training mode during that time. Maybe the other OS that you tried simply uses longer timeouts before it disconnects the session and does a reconnect.

gbosco · Jan 9, 2007, 7:01 PM

modified /var/etc/mpd.conf, and set a more generous timing when MPD determines LCP echo timeout.

set link keep-alive 30 300

(it was: set link keep-alive 10 60)

I didn´t loose the connection for more than 24 hours now - which is a record!

I would wish pfSense had a feature under PPPoE, where it is possible to set those values.

Thanks to anyone who participated to this thread.

/gbosco