2.0.3 -> 2.1.3 : weird & unstable PPPOE link



  • Hi,

    I experience problem with the PPPOE after a 2.0.3 -> 2.1.3 upgrade.

    I came from a rock stable 2.0.3, no xDSL link lost, 8 month uptime, in short working like a charm.

    Since upgrading to 2.1.3, it's really hard to maintain something up for 24H.

    Here is the today logs :

    May 26 03:27:06 ppp: caught fatal signal term
    May 26 03:27:06 ppp: [wan] IFACE: Close event
    May 26 03:27:06 ppp: [wan] IPCP: Close event
    May 26 03:27:06 ppp: [wan] IPCP: state change Opened –> Closing
    May 26 03:27:06 ppp: [wan] IPCP: SendTerminateReq #4
    May 26 03:27:06 ppp: [wan] IPCP: LayerDown
    May 26 03:27:06 ppp: [wan] IFACE: Delete route 0.0.0.0/0 yyy.yyy.yyy.yyy failed: No such process
    May 26 03:27:06 ppp: [wan] IFACE: Down event
    May 26 03:27:06 ppp: [wan] IFACE: Rename interface pppoe0 to pppoe0
    May 26 03:27:06 ppp: [wan] IPV6CP: Close event
    May 26 03:27:06 ppp: [wan] IPV6CP: state change Stopped –> Closed
    May 26 03:27:06 ppp: [wan] IPCP: rec'd Terminate Ack #4 (Closing)
    May 26 03:27:06 ppp: [wan] IPCP: state change Closing –> Closed
    May 26 03:27:06 ppp: [wan] IPCP: LayerFinish
    May 26 03:27:06 ppp: [wan] Bundle: No NCPs left. Closing links…
    May 26 03:27:06 ppp: [wan] Bundle: closing link "wan_link0"…
    May 26 03:27:06 ppp: [wan_link0] LCP: rec'd Terminate Request #74 (Opened)
    May 26 03:27:06 ppp: [wan_link0] LCP: state change Opened –> Stopping
    May 26 03:27:06 ppp: [wan_link0] Link: Leave bundle "wan"
    May 26 03:27:06 ppp: [wan] Bundle: Status update: up 0 links, total bandwidth 9600 bps
    May 26 03:27:06 ppp: [wan] IPCP: Close event
    May 26 03:27:06 ppp: [wan] IPV6CP: Close event
    May 26 03:27:06 ppp: [wan] IPCP: Down event
    May 26 03:27:06 ppp: [wan] IPCP: state change Closed –> Initial
    May 26 03:27:06 ppp: [wan] IPV6CP: Down event
    May 26 03:27:06 ppp: [wan] IPV6CP: state change Closed –> Initial
    May 26 03:27:06 ppp: [wan_link0] LCP: SendTerminateAck #4
    May 26 03:27:06 ppp: [wan_link0] LCP: LayerDown
    May 26 03:27:06 ppp: [wan_link0] Link: CLOSE event
    May 26 03:27:06 ppp: [wan_link0] LCP: Close event
    May 26 03:27:06 ppp: [wan_link0] LCP: state change Stopping –> Closing
    May 26 03:27:06 ppp: Multi-link PPP daemon for FreeBSD
    May 26 03:27:06 ppp:
    May 26 03:27:06 ppp: process 69759 started, version 5.7 (root@snapshots-8_3-i386.builders.pfsense.org 19:47 27-Mar-2014)
    May 26 03:27:06 ppp: waiting for process 19830 to die...
    May 26 03:27:06 ppp: Multi-link PPP daemon for FreeBSD
    May 26 03:27:06 ppp:
    May 26 03:27:06 ppp: process 70280 started, version 5.7 (root@snapshots-8_3-i386.builders.pfsense.org 19:47 27-Mar-2014)
    May 26 03:27:06 ppp: waiting for process 19830 to die...
    May 26 03:27:07 ppp: waiting for process 19830 to die...
    May 26 03:27:07 ppp: waiting for process 19830 to die...
    May 26 03:27:08 ppp: [wan] Bundle: Shutdown
    May 26 03:27:08 ppp: [wan_link0] Link: Shutdown
    May 26 03:27:08 ppp: process 19830 terminated
    May 26 03:27:08 ppp: waiting for process 69759 to die…
    May 26 03:27:09 ppp: OpenConfFile: Can't open file '/var/etc/mpd_wan.conf': No such file or directory
    May 26 03:27:09 ppp: OpenConfFile: Can't open file '/var/etc/mpd_wan.conf': No such file or directory
    May 26 03:27:09 ppp: can't read configuration for "pppoeclient"
    May 26 03:27:09 ppp: process 70280 terminated

    --> Manually connect the PPP from web interface at 07:38

    May 26 07:38:04 ppp: Multi-link PPP daemon for FreeBSD
    May 26 07:38:04 ppp:
    May 26 07:38:04 ppp: process 5909 started, version 5.7 (root@snapshots-8_3-i386.builders.pfsense.org 19:47 27-Mar-2014)
    May 26 07:38:04 ppp: web: web is not running
    May 26 07:38:04 ppp: [wan] Bundle: Interface ng0 created
    May 26 07:38:04 ppp: [wan_link0] Link: OPEN event
    May 26 07:38:04 ppp: [wan_link0] LCP: Open event
    May 26 07:38:04 ppp: [wan_link0] LCP: state change Initial –> Starting
    May 26 07:38:04 ppp: [wan_link0] LCP: LayerStart
    May 26 07:38:04 ppp: [wan_link0] PPPoE: Connecting to ''
    May 26 07:38:04 ppp: PPPoE: rec'd ACNAME "SE1200-GNB-1"
    May 26 07:38:05 ppp: [wan_link0] PPPoE: connection successful
    May 26 07:38:05 ppp: [wan_link0] Link: UP event
    May 26 07:38:05 ppp: [wan_link0] LCP: Up event
    May 26 07:38:05 ppp: [wan_link0] LCP: state change Starting –> Req-Sent
    May 26 07:38:05 ppp: [wan_link0] LCP: SendConfigReq #1
    May 26 07:38:05 ppp: [wan_link0] PROTOCOMP
    May 26 07:38:05 ppp: [wan_link0] MRU 1492
    May 26 07:38:05 ppp: [wan_link0] MAGICNUM 947e5b5c
    May 26 07:38:05 ppp: [wan_link0] LCP: rec'd Configure Request #104 (Req-Sent)
    May 26 07:38:05 ppp: [wan_link0] MRU 1492
    May 26 07:38:05 ppp: [wan_link0] AUTHPROTO CHAP MD5
    May 26 07:38:05 ppp: [wan_link0] MAGICNUM 231bf26b
    May 26 07:38:05 ppp: [wan_link0] LCP: SendConfigAck #104
    May 26 07:38:05 ppp: [wan_link0] MRU 1492
    May 26 07:38:05 ppp: [wan_link0] AUTHPROTO CHAP MD5
    May 26 07:38:05 ppp: [wan_link0] MAGICNUM 231bf26b
    May 26 07:38:05 ppp: [wan_link0] LCP: state change Req-Sent –> Ack-Sent
    May 26 07:38:05 ppp: [wan_link0] LCP: rec'd Configure Reject #1 (Ack-Sent)
    May 26 07:38:05 ppp: [wan_link0] PROTOCOMP
    May 26 07:38:05 ppp: [wan_link0] LCP: SendConfigReq #2
    May 26 07:38:05 ppp: [wan_link0] MRU 1492
    May 26 07:38:05 ppp: [wan_link0] MAGICNUM 947e5b5c
    May 26 07:38:05 ppp: [wan_link0] LCP: rec'd Configure Ack #2 (Ack-Sent)
    May 26 07:38:05 ppp: [wan_link0] MRU 1492
    May 26 07:38:05 ppp: [wan_link0] MAGICNUM 947e5b5c
    May 26 07:38:05 ppp: [wan_link0] LCP: state change Ack-Sent –> Opened
    May 26 07:38:05 ppp: [wan_link0] LCP: auth: peer wants CHAP, I want nothing
    May 26 07:38:05 ppp: [wan_link0] LCP: LayerUp
    May 26 07:38:05 ppp: [wan_link0] CHAP: rec'd CHALLENGE #1 len: 33
    May 26 07:38:05 ppp: [wan_link0] Name: "SE1200-GNB-1"
    May 26 07:38:05 ppp: [wan_link0] CHAP: Using authname "xxxxxxxxxxxxxxx"
    May 26 07:38:05 ppp: [wan_link0] CHAP: sending RESPONSE #1 len: 42
    May 26 07:38:05 ppp: [wan_link0] LCP: rec'd Configure Request #65 (Opened)
    May 26 07:38:05 ppp: [wan_link0] MRU 1492
    May 26 07:38:05 ppp: [wan_link0] AUTHPROTO CHAP MD5
    May 26 07:38:05 ppp: [wan_link0] MAGICNUM 231bf26b
    May 26 07:38:05 ppp: [wan_link0] LCP: LayerDown
    May 26 07:38:05 ppp: [wan_link0] LCP: SendConfigReq #3
    May 26 07:38:05 ppp: [wan_link0] MRU 1492
    May 26 07:38:05 ppp: [wan_link0] MAGICNUM 947e5b5c
    May 26 07:38:05 ppp: [wan_link0] LCP: SendConfigAck #65
    May 26 07:38:05 ppp: [wan_link0] MRU 1492
    May 26 07:38:05 ppp: [wan_link0] AUTHPROTO CHAP MD5
    May 26 07:38:05 ppp: [wan_link0] MAGICNUM 231bf26b
    May 26 07:38:05 ppp: [wan_link0] LCP: state change Opened –> Ack-Sent
    May 26 07:38:05 ppp: [wan_link0] LCP: rec'd Configure Ack #3 (Ack-Sent)
    May 26 07:38:05 ppp: [wan_link0] MRU 1492
    May 26 07:38:05 ppp: [wan_link0] MAGICNUM 947e5b5c
    May 26 07:38:05 ppp: [wan_link0] LCP: state change Ack-Sent –> Opened
    May 26 07:38:05 ppp: [wan_link0] LCP: auth: peer wants CHAP, I want nothing
    May 26 07:38:05 ppp: [wan_link0] LCP: LayerUp
    May 26 07:38:05 ppp: [wan_link0] CHAP: rec'd CHALLENGE #1 len: 37
    May 26 07:38:05 ppp: [wan_link0] Name: "lns-1-lyo-se1200"
    May 26 07:38:05 ppp: [wan_link0] CHAP: Using authname "xxxxxxxxxxxxxxx"
    May 26 07:38:05 ppp: [wan_link0] CHAP: sending RESPONSE #1 len: 42
    May 26 07:38:05 ppp: [wan_link0] CHAP: rec'd SUCCESS #1 len: 42
    May 26 07:38:05 ppp: [wan_link0] MESG: CHAP authentication success, unit 1574
    May 26 07:38:05 ppp: [wan_link0] LCP: authorization successful
    May 26 07:38:05 ppp: [wan_link0] Link: Matched action 'bundle "wan" ""'
    May 26 07:38:05 ppp: [wan_link0] Link: Join bundle "wan"
    May 26 07:38:05 ppp: [wan] Bundle: Status update: up 1 link, total bandwidth 64000 bps
    May 26 07:38:05 ppp: [wan] IPCP: Open event
    May 26 07:38:05 ppp: [wan] IPCP: state change Initial –> Starting
    May 26 07:38:05 ppp: [wan] IPCP: LayerStart
    May 26 07:38:05 ppp: [wan] IPV6CP: Open event
    May 26 07:38:05 ppp: [wan] IPV6CP: state change Initial –> Starting
    May 26 07:38:05 ppp: [wan] IPV6CP: LayerStart
    May 26 07:38:05 ppp: [wan] IPCP: Up event
    May 26 07:38:05 ppp: [wan] IPCP: state change Starting –> Req-Sent
    May 26 07:38:05 ppp: [wan] IPCP: SendConfigReq #1
    May 26 07:38:05 ppp: [wan] IPADDR 0.0.0.0
    May 26 07:38:05 ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
    May 26 07:38:05 ppp: [wan] PRIDNS 0.0.0.0
    May 26 07:38:05 ppp: [wan] SECDNS 0.0.0.0
    May 26 07:38:05 ppp: [wan] IPV6CP: Up event
    May 26 07:38:05 ppp: [wan] IPV6CP: state change Starting –> Req-Sent
    May 26 07:38:05 ppp: [wan] IPV6CP: SendConfigReq #1
    May 26 07:38:05 ppp: [wan] IPCP: rec'd Configure Request #132 (Req-Sent)
    May 26 07:38:05 ppp: [wan] IPADDR yyy.yyy.yyy.yyy
    May 26 07:38:05 ppp: [wan] yyy.yyy.yyy.yyy is OK
    May 26 07:38:05 ppp: [wan] IPCP: SendConfigAck #132
    May 26 07:38:05 ppp: [wan] IPADDR yyy.yyy.yyy.yyy
    May 26 07:38:05 ppp: [wan] IPCP: state change Req-Sent –> Ack-Sent
    May 26 07:38:05 ppp: [wan] IPCP: rec'd Configure Reject #1 (Ack-Sent)
    May 26 07:38:05 ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
    May 26 07:38:05 ppp: [wan] IPCP: SendConfigReq #2
    May 26 07:38:05 ppp: [wan] IPADDR 0.0.0.0
    May 26 07:38:05 ppp: [wan] PRIDNS 0.0.0.0
    May 26 07:38:05 ppp: [wan] SECDNS 0.0.0.0
    May 26 07:38:05 ppp: [wan_link0] LCP: rec'd Protocol Reject #66 (Opened)
    May 26 07:38:05 ppp: [wan_link0] LCP: protocol IPV6CP was rejected
    May 26 07:38:05 ppp: [wan] IPV6CP: protocol was rejected by peer
    May 26 07:38:05 ppp: [wan] IPV6CP: state change Req-Sent –> Stopped
    May 26 07:38:05 ppp: [wan] IPV6CP: LayerFinish
    May 26 07:38:05 ppp: [wan] IPCP: rec'd Configure Nak #2 (Ack-Sent)
    May 26 07:38:05 ppp: [wan] IPADDR xxx.xxx.xxx.xxx
    May 26 07:38:05 ppp: [wan] xxx.xxx.xxx.xxx is OK
    May 26 07:38:05 ppp: [wan] PRIDNS 91.121.161.184
    May 26 07:38:05 ppp: [wan] SECDNS 188.165.197.144
    May 26 07:38:05 ppp: [wan] IPCP: SendConfigReq #3
    May 26 07:38:05 ppp: [wan] IPADDR xxx.xxx.xxx.xxx
    May 26 07:38:05 ppp: [wan] PRIDNS 91.121.161.184
    May 26 07:38:05 ppp: [wan] SECDNS 188.165.197.144
    May 26 07:38:05 ppp: [wan] IPCP: rec'd Configure Ack #3 (Ack-Sent)
    May 26 07:38:05 ppp: [wan] IPADDR xxx.xxx.xxx.xxx
    May 26 07:38:05 ppp: [wan] PRIDNS 91.121.161.184
    May 26 07:38:05 ppp: [wan] SECDNS 188.165.197.144
    May 26 07:38:05 ppp: [wan] IPCP: state change Ack-Sent –> Opened
    May 26 07:38:05 ppp: [wan] IPCP: LayerUp
    May 26 07:38:05 ppp: [wan] xxx.xxx.xxx.xxx -> yyy.yyy.yyy.yyy
    May 26 07:38:06 ppp: [wan] IFACE: Up event
    May 26 07:38:06 ppp: [wan] IFACE: Rename interface ng0 to pppoe0
    May 26 16:23:30 ppp: caught fatal signal term
    May 26 16:23:30 ppp: [wan] IFACE: Close event
    May 26 16:23:30 ppp: [wan] IPCP: Close event
    May 26 16:23:30 ppp: [wan] IPCP: state change Opened –> Closing
    May 26 16:23:30 ppp: [wan] IPCP: SendTerminateReq #4
    May 26 16:23:30 ppp: [wan] IPCP: LayerDown
    May 26 16:23:31 ppp: [wan] IFACE: Delete route 0.0.0.0/0 yyy.yyy.yyy.yyy failed: No such process
    May 26 16:23:31 ppp: [wan] IFACE: Removing IPv4 address from pppoe0 failed(IGNORING for now. This should be only for PPPoE friendly!): Can't assign requested address
    May 26 16:23:31 ppp: [wan] IFACE: Down event
    May 26 16:23:31 ppp: [wan] IFACE: Rename interface pppoe0 to pppoe0
    May 26 16:23:31 ppp: [wan] IPV6CP: Close event
    May 26 16:23:31 ppp: [wan] IPV6CP: state change Stopped –> Closed
    May 26 16:23:31 ppp: [wan] IPCP: rec'd Terminate Ack #4 (Closing)
    May 26 16:23:31 ppp: [wan] IPCP: state change Closing –> Closed
    May 26 16:23:31 ppp: [wan] IPCP: LayerFinish
    May 26 16:23:31 ppp: [wan] Bundle: No NCPs left. Closing links…
    May 26 16:23:31 ppp: [wan] Bundle: closing link "wan_link0"…
    May 26 16:23:31 ppp: [wan_link0] LCP: rec'd Terminate Request #67 (Opened)
    May 26 16:23:31 ppp: [wan_link0] LCP: state change Opened –> Stopping
    May 26 16:23:31 ppp: [wan_link0] Link: Leave bundle "wan"
    May 26 16:23:31 ppp: [wan] Bundle: Status update: up 0 links, total bandwidth 9600 bps
    May 26 16:23:31 ppp: [wan] IPCP: Close event
    May 26 16:23:31 ppp: [wan] IPV6CP: Close event
    May 26 16:23:31 ppp: [wan] IPCP: Down event
    May 26 16:23:31 ppp: [wan] IPCP: state change Closed –> Initial
    May 26 16:23:31 ppp: [wan] IPV6CP: Down event
    May 26 16:23:31 ppp: [wan] IPV6CP: state change Closed –> Initial
    May 26 16:23:31 ppp: [wan_link0] LCP: SendTerminateAck #4
    May 26 16:23:31 ppp: [wan_link0] LCP: LayerDown
    May 26 16:23:31 ppp: [wan_link0] Link: CLOSE event
    May 26 16:23:31 ppp: [wan_link0] LCP: Close event
    May 26 16:23:31 ppp: [wan_link0] LCP: state change Stopping –> Closing
    May 26 16:23:31 ppp: Multi-link PPP daemon for FreeBSD
    May 26 16:23:31 ppp:
    May 26 16:23:31 ppp: process 19539 started, version 5.7 (root@snapshots-8_3-i386.builders.pfsense.org 19:47 27-Mar-2014)
    May 26 16:23:31 ppp: waiting for process 5909 to die...
    May 26 16:23:32 ppp: waiting for process 5909 to die...
    May 26 16:23:33 ppp: waiting for process 5909 to die...
    May 26 16:23:33 ppp: [wan_link0] LCP: state change Closing –> Closed
    May 26 16:23:33 ppp: [wan_link0] LCP: LayerFinish
    May 26 16:23:33 ppp: [wan] Bundle: Shutdown
    May 26 16:23:33 ppp: [wan_link0] Link: Shutdown
    May 26 16:23:33 ppp: process 5909 terminated
    May 26 16:23:34 ppp: OpenConfFile: Can't open file '/var/etc/mpd_wan.conf': No such file or directory
    May 26 16:23:34 ppp: OpenConfFile: Can't open file '/var/etc/mpd_wan.conf': No such file or directory
    May 26 16:23:34 ppp: can't read configuration for "pppoeclient"
    May 26 16:23:34 ppp: process 19539 terminated

    –> here, no internet cnx, no action from me, PfSense brings back the PPP at 17h31

    May 26 17:31:33 ppp: Multi-link PPP daemon for FreeBSD
    May 26 17:31:33 ppp:
    May 26 17:31:33 ppp: process 34353 started, version 5.7 (root@snapshots-8_3-i386.builders.pfsense.org 19:47 27-Mar-2014)
    May 26 17:31:33 ppp: web: web is not running
    May 26 17:31:33 ppp: [wan] Bundle: Interface ng0 created
    May 26 17:31:33 ppp: [wan_link0] Link: OPEN event
    May 26 17:31:33 ppp: [wan_link0] LCP: Open event
    May 26 17:31:33 ppp: [wan_link0] LCP: state change Initial –> Starting
    May 26 17:31:33 ppp: [wan_link0] LCP: LayerStart
    May 26 17:31:33 ppp: [wan_link0] PPPoE: Connecting to ''
    May 26 17:31:33 ppp: PPPoE: rec'd ACNAME "SE1200-GNB-1"
    May 26 17:31:33 ppp: [wan_link0] PPPoE: connection successful
    May 26 17:31:33 ppp: [wan_link0] Link: UP event
    May 26 17:31:33 ppp: [wan_link0] LCP: Up event
    May 26 17:31:33 ppp: [wan_link0] LCP: state change Starting –> Req-Sent
    May 26 17:31:33 ppp: [wan_link0] LCP: SendConfigReq #1
    May 26 17:31:33 ppp: [wan_link0] PROTOCOMP
    May 26 17:31:33 ppp: [wan_link0] MRU 1492
    May 26 17:31:33 ppp: [wan_link0] MAGICNUM d7851407
    May 26 17:31:33 ppp: [wan_link0] LCP: rec'd Configure Request #238 (Req-Sent)
    May 26 17:31:33 ppp: [wan_link0] MRU 1492
    May 26 17:31:33 ppp: [wan_link0] AUTHPROTO CHAP MD5
    May 26 17:31:33 ppp: [wan_link0] MAGICNUM 3faac796
    May 26 17:31:33 ppp: [wan_link0] LCP: SendConfigAck #238
    May 26 17:31:33 ppp: [wan_link0] MRU 1492
    May 26 17:31:33 ppp: [wan_link0] AUTHPROTO CHAP MD5
    May 26 17:31:33 ppp: [wan_link0] MAGICNUM 3faac796
    May 26 17:31:33 ppp: [wan_link0] LCP: state change Req-Sent –> Ack-Sent
    May 26 17:31:33 ppp: [wan_link0] LCP: rec'd Configure Reject #1 (Ack-Sent)
    May 26 17:31:33 ppp: [wan_link0] PROTOCOMP
    May 26 17:31:33 ppp: [wan_link0] LCP: SendConfigReq #2
    May 26 17:31:33 ppp: [wan_link0] MRU 1492
    May 26 17:31:33 ppp: [wan_link0] MAGICNUM d7851407
    May 26 17:31:34 ppp: [wan_link0] LCP: rec'd Configure Ack #2 (Ack-Sent)
    May 26 17:31:34 ppp: [wan_link0] MRU 1492
    May 26 17:31:34 ppp: [wan_link0] MAGICNUM d7851407
    May 26 17:31:34 ppp: [wan_link0] LCP: state change Ack-Sent –> Opened
    May 26 17:31:34 ppp: [wan_link0] LCP: auth: peer wants CHAP, I want nothing
    May 26 17:31:34 ppp: [wan_link0] LCP: LayerUp
    May 26 17:31:34 ppp: [wan_link0] CHAP: rec'd CHALLENGE #1 len: 33
    May 26 17:31:34 ppp: [wan_link0] Name: "SE1200-GNB-1"
    May 26 17:31:34 ppp: [wan_link0] CHAP: Using authname "xxxxxxxxxxxxxxx"
    May 26 17:31:34 ppp: [wan_link0] CHAP: sending RESPONSE #1 len: 42
    May 26 17:31:36 ppp: [wan_link0] CHAP: sending RESPONSE #1 len: 42
    May 26 17:31:36 ppp: [wan_link0] CHAP: rec'd FAILURE #1 len: 18
    May 26 17:31:36 ppp: [wan_link0] MESG: Request Denied
    May 26 17:31:36 ppp: [wan_link0] LCP: authorization failed
    May 26 17:31:36 ppp: [wan_link0] LCP: parameter negotiation failed
    May 26 17:31:36 ppp: [wan_link0] LCP: state change Opened –> Stopping
    May 26 17:31:36 ppp: [wan_link0] LCP: SendTerminateReq #3
    May 26 17:31:36 ppp: [wan_link0] LCP: LayerDown
    May 26 17:31:36 ppp: [wan_link0] LCP: rec'd Terminate Request #239 (Stopping)
    May 26 17:31:36 ppp: [wan_link0] LCP: SendTerminateAck #4
    May 26 17:31:36 ppp: [wan_link0] LCP: rec'd Terminate Ack #3 (Stopping)
    May 26 17:31:36 ppp: [wan_link0] LCP: state change Stopping –> Stopped
    May 26 17:31:36 ppp: [wan_link0] LCP: LayerFinish
    May 26 17:31:36 ppp: [wan_link0] PPPoE: connection closed
    May 26 17:31:36 ppp: [wan_link0] Link: DOWN event
    May 26 17:31:36 ppp: [wan_link0] LCP: Down event
    May 26 17:31:36 ppp: [wan_link0] LCP: state change Stopped –> Starting
    May 26 17:31:36 ppp: [wan_link0] LCP: LayerStart
    May 26 17:31:36 ppp: [wan_link0] Link: reconnection attempt 1 in 4 seconds
    May 26 17:31:40 ppp: [wan_link0] Link: reconnection attempt 1
    May 26 17:31:40 ppp: [wan_link0] PPPoE: Connecting to ''
    May 26 17:31:40 ppp: PPPoE: rec'd ACNAME "SE1200-GNB-1"
    May 26 17:31:40 ppp: [wan_link0] PPPoE: connection successful
    May 26 17:31:40 ppp: [wan_link0] Link: UP event
    May 26 17:31:40 ppp: [wan_link0] LCP: Up event
    May 26 17:31:40 ppp: [wan_link0] LCP: state change Starting –> Req-Sent
    May 26 17:31:40 ppp: [wan_link0] LCP: SendConfigReq #5
    May 26 17:31:40 ppp: [wan_link0] PROTOCOMP
    May 26 17:31:40 ppp: [wan_link0] MRU 1492
    May 26 17:31:40 ppp: [wan_link0] MAGICNUM 95865b7f
    May 26 17:31:40 ppp: [wan_link0] LCP: rec'd Configure Request #128 (Req-Sent)
    May 26 17:31:40 ppp: [wan_link0] MRU 1492
    May 26 17:31:40 ppp: [wan_link0] AUTHPROTO CHAP MD5
    May 26 17:31:40 ppp: [wan_link0] MAGICNUM 63590dca
    May 26 17:31:40 ppp: [wan_link0] LCP: SendConfigAck #128
    May 26 17:31:40 ppp: [wan_link0] MRU 1492
    May 26 17:31:40 ppp: [wan_link0] AUTHPROTO CHAP MD5
    May 26 17:31:40 ppp: [wan_link0] MAGICNUM 63590dca
    May 26 17:31:40 ppp: [wan_link0] LCP: state change Req-Sent –> Ack-Sent
    May 26 17:31:40 ppp: [wan_link0] LCP: rec'd Configure Reject #5 (Ack-Sent)
    May 26 17:31:40 ppp: [wan_link0] PROTOCOMP
    May 26 17:31:40 ppp: [wan_link0] LCP: SendConfigReq #6
    May 26 17:31:40 ppp: [wan_link0] MRU 1492
    May 26 17:31:40 ppp: [wan_link0] MAGICNUM 95865b7f
    May 26 17:31:40 ppp: [wan_link0] LCP: rec'd Configure Ack #6 (Ack-Sent)
    May 26 17:31:40 ppp: [wan_link0] MRU 1492
    May 26 17:31:40 ppp: [wan_link0] MAGICNUM 95865b7f
    May 26 17:31:40 ppp: [wan_link0] LCP: state change Ack-Sent –> Opened
    May 26 17:31:40 ppp: [wan_link0] LCP: auth: peer wants CHAP, I want nothing
    May 26 17:31:40 ppp: [wan_link0] LCP: LayerUp
    May 26 17:31:40 ppp: [wan_link0] CHAP: rec'd CHALLENGE #1 len: 33
    May 26 17:31:40 ppp: [wan_link0] Name: "SE1200-GNB-1"
    May 26 17:31:40 ppp: [wan_link0] CHAP: Using authname "xxxxxxxxxxxxxxx"
    May 26 17:31:40 ppp: [wan_link0] CHAP: sending RESPONSE #1 len: 42
    May 26 17:31:41 ppp: [wan_link0] LCP: rec'd Configure Request #54 (Opened)
    May 26 17:31:41 ppp: [wan_link0] MRU 1492
    May 26 17:31:41 ppp: [wan_link0] AUTHPROTO CHAP MD5
    May 26 17:31:41 ppp: [wan_link0] MAGICNUM 63590dca
    May 26 17:31:41 ppp: [wan_link0] LCP: LayerDown
    May 26 17:31:41 ppp: [wan_link0] LCP: SendConfigReq #7
    May 26 17:31:41 ppp: [wan_link0] MRU 1492
    May 26 17:31:41 ppp: [wan_link0] MAGICNUM 95865b7f
    May 26 17:31:41 ppp: [wan_link0] LCP: SendConfigAck #54
    May 26 17:31:41 ppp: [wan_link0] MRU 1492
    May 26 17:31:41 ppp: [wan_link0] AUTHPROTO CHAP MD5
    May 26 17:31:41 ppp: [wan_link0] MAGICNUM 63590dca
    May 26 17:31:41 ppp: [wan_link0] LCP: state change Opened –> Ack-Sent
    May 26 17:31:41 ppp: [wan_link0] LCP: rec'd Configure Ack #7 (Ack-Sent)
    May 26 17:31:41 ppp: [wan_link0] MRU 1492
    May 26 17:31:41 ppp: [wan_link0] MAGICNUM 95865b7f
    May 26 17:31:41 ppp: [wan_link0] LCP: state change Ack-Sent –> Opened
    May 26 17:31:41 ppp: [wan_link0] LCP: auth: peer wants CHAP, I want nothing
    May 26 17:31:41 ppp: [wan_link0] LCP: LayerUp
    May 26 17:31:41 ppp: [wan_link0] CHAP: rec'd CHALLENGE #1 len: 37
    May 26 17:31:41 ppp: [wan_link0] Name: "lns-1-lyo-se1200"
    May 26 17:31:41 ppp: [wan_link0] CHAP: Using authname "xxxxxxxxxxxxxxx"
    May 26 17:31:41 ppp: [wan_link0] CHAP: sending RESPONSE #1 len: 42
    May 26 17:31:41 ppp: [wan_link0] CHAP: rec'd SUCCESS #1 len: 42
    May 26 17:31:41 ppp: [wan_link0] MESG: CHAP authentication success, unit 3270
    May 26 17:31:41 ppp: [wan_link0] LCP: authorization successful
    May 26 17:31:41 ppp: [wan_link0] Link: Matched action 'bundle "wan" ""'
    May 26 17:31:41 ppp: [wan_link0] Link: Join bundle "wan"
    May 26 17:31:41 ppp: [wan] Bundle: Status update: up 1 link, total bandwidth 64000 bps
    May 26 17:31:41 ppp: [wan] IPCP: Open event
    May 26 17:31:41 ppp: [wan] IPCP: state change Initial –> Starting
    May 26 17:31:41 ppp: [wan] IPCP: LayerStart
    May 26 17:31:41 ppp: [wan] IPV6CP: Open event
    May 26 17:31:41 ppp: [wan] IPV6CP: state change Initial –> Starting
    May 26 17:31:41 ppp: [wan] IPV6CP: LayerStart
    May 26 17:31:41 ppp: [wan] IPCP: Up event
    May 26 17:31:41 ppp: [wan] IPCP: state change Starting –> Req-Sent
    May 26 17:31:41 ppp: [wan] IPCP: SendConfigReq #1
    May 26 17:31:41 ppp: [wan] IPADDR 0.0.0.0
    May 26 17:31:41 ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
    May 26 17:31:41 ppp: [wan] PRIDNS 0.0.0.0
    May 26 17:31:41 ppp: [wan] SECDNS 0.0.0.0
    May 26 17:31:41 ppp: [wan] IPV6CP: Up event
    May 26 17:31:41 ppp: [wan] IPV6CP: state change Starting –> Req-Sent
    May 26 17:31:41 ppp: [wan] IPV6CP: SendConfigReq #1
    May 26 17:31:41 ppp: [wan] IPCP: rec'd Configure Request #132 (Req-Sent)
    May 26 17:31:41 ppp: [wan] IPADDR yyy.yyy.yyy.yyy
    May 26 17:31:41 ppp: [wan] yyy.yyy.yyy.yyy is OK
    May 26 17:31:41 ppp: [wan] IPCP: SendConfigAck #132
    May 26 17:31:41 ppp: [wan] IPADDR yyy.yyy.yyy.yyy
    May 26 17:31:41 ppp: [wan] IPCP: state change Req-Sent –> Ack-Sent
    May 26 17:31:41 ppp: [wan] IPCP: rec'd Configure Reject #1 (Ack-Sent)
    May 26 17:31:41 ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
    May 26 17:31:41 ppp: [wan] IPCP: SendConfigReq #2
    May 26 17:31:41 ppp: [wan] IPADDR 0.0.0.0
    May 26 17:31:41 ppp: [wan] PRIDNS 0.0.0.0
    May 26 17:31:41 ppp: [wan] SECDNS 0.0.0.0
    May 26 17:31:41 ppp: [wan_link0] LCP: rec'd Protocol Reject #55 (Opened)
    May 26 17:31:41 ppp: [wan_link0] LCP: protocol IPV6CP was rejected
    May 26 17:31:41 ppp: [wan] IPV6CP: protocol was rejected by peer
    May 26 17:31:41 ppp: [wan] IPV6CP: state change Req-Sent –> Stopped
    May 26 17:31:41 ppp: [wan] IPV6CP: LayerFinish
    May 26 17:31:41 ppp: [wan] IPCP: rec'd Configure Nak #2 (Ack-Sent)
    May 26 17:31:41 ppp: [wan] IPADDR xxx.xxx.xxx.xxx
    May 26 17:31:41 ppp: [wan] xxx.xxx.xxx.xxx is OK
    May 26 17:31:41 ppp: [wan] PRIDNS 91.121.161.184
    May 26 17:31:41 ppp: [wan] SECDNS 188.165.197.144
    May 26 17:31:41 ppp: [wan] IPCP: SendConfigReq #3
    May 26 17:31:41 ppp: [wan] IPADDR xxx.xxx.xxx.xxx
    May 26 17:31:41 ppp: [wan] PRIDNS 91.121.161.184
    May 26 17:31:41 ppp: [wan] SECDNS 188.165.197.144
    May 26 17:31:41 ppp: [wan] IPCP: rec'd Configure Ack #3 (Ack-Sent)
    May 26 17:31:41 ppp: [wan] IPADDR xxx.xxx.xxx.xxx
    May 26 17:31:41 ppp: [wan] PRIDNS 91.121.161.184
    May 26 17:31:41 ppp: [wan] SECDNS 188.165.197.144
    May 26 17:31:41 ppp: [wan] IPCP: state change Ack-Sent –> Opened
    May 26 17:31:41 ppp: [wan] IPCP: LayerUp
    May 26 17:31:41 ppp: [wan] xxx.xxx.xxx.xxx -> yyy.yyy.yyy.yyy
    May 26 17:31:42 ppp: [wan] IFACE: Up event
    May 26 17:31:42 ppp: [wan] IFACE: Rename interface ng0 to pppoe0

    I have tried to rise-up the threshold values of the WAN link, no effect.
    I have tried to disable "Hardware Checksum Offloading", no effect.
    Those 2 advices came from the forum & worth a try.

    I'm stuck on this one … Seems the PPP daemon gets mad, but I can't figure why.

    Would appreciate some helps on this one.

    Cheers,

    Phil



  • maybe try a fresh install of 2.1.3?



  • @val:

    maybe try a fresh install of 2.1.3?

    As the upgrade already trash the RRD graphs, yes I could do that  :). But according to my experience I bet this will not solve the problem …



  • I think my problem is not new & already referenced : https://redmine.pfsense.org/issues/1943

    How can I help to solve this one ? Need other logs, something to try ?



  • I am also experiencing this exact misbehavior at one of my client sites.

    Running 2.1.3-RELEASE (i386).

    We have a fairly solid radio link implemented, but inclement weather is periodically–and understandably--disrupting the PPPoE session.  Every single time the PPPoE session is disrupted, the pfSense device must be rebooted or somebody must log into the GUI and manually click the ‘Connect’ button.  Fortunately my client is being very understanding and patient.  Until this issue is resolved, we pray for clear skies!

    There is mention in the history of Bug #1943 that this issue may only be related to the ‘vr’ interface driver.  However, in my case, the interface driver is ‘bge’ (Broadcom).



  • As an aside, I upgraded my client’s appliance to 2.1.4-RELEASE (i386) and the problem persists.  Of course I really didn’t expect this latest security release to resolve our particular PPPoE issue.

    Based on everything I have read so far, this issue seems to be isolated to the “Embedded” (NanoBSD) edition of pfSense.  The Embedded edition of pfSense is optimized for hardware that uses any variation of flash memory as the system drive (as opposed to a traditional spindle hard drive).

    This morning I swapped in a different pfSense computer at my client…one that has a traditional hard drive, and thus is running the regular edition of pfSense.  As anticipated, it worked like a charm when I simulated a PPPoE interruption by simply disconnecting the cable to the WAN interface.  After I plugged the cable back in, pfSense was able to re-establish the PPPoE session in about 30 seconds.

    I know this test didn’t come close to abiding by the Scientific Method—many, many variables were changed at once.  Nevertheless, based on what I have read so far, I still feel the Embedded edition is highly suspect with respect to this PPPoE issue.



  • Hi,

    I run the "regular" version with an HDD & Squid proxy.
    And in my case the problem appears with the upgrade from the 2.0.X to 2.1.X version.

    To my guess (as scientific as ours :) ) it's more a kernel module version or something related who trig the bug.

    I didn't solved it yet :(. And I have heavily play with this damn one …

    Cheers,

    Phil



  • That’s a very helpful diagnostic, and I will no longer suspect the Embedded edition!

    Given your input Phil, and now that I have an alternative pfSense appliance at my client site, I am going to completely re-install pfSense on my first device to see if the PPPoE problem is magically fixed by a fresh re-install.  I anticipate that a re-install will not fix the problem, but I want to put a nail in that coffin because it may be suggested or requested by a pfSense developer.

    Out of curiosity Phil, what is the make of the WAN interface on your problematic unit (e.g., Intel, Broadcom, etc.)?  I may be overlooking this information in your PPP log.