PPPoE reconenction fix - mpd fix ($100)



  • all the pfsense nanobsd v2+ have one pppoe reconnection issue related to the newer mpd being used and i desperately need a fix for it, this has been talked over and over again and again but most of the ppl out there dont have this issue but there r a few including me who face this.

    mpd, pppoe etc logs have been provided but hasn’t yet yielded anything and mostly the culprit is mpd itself coz the older pfsense and older mpd used to work flawless and used to reconnect perfectly even with cable unplug or isp router fail etc.

    the issue is as follows:
    on pfsense reboot, pppoe connects fine and everything working. once u unplug the cable between the isp router and pfsense then connection drops but as soon as replug it, it resumes fine, myb because the isp modem still remains in its configured state. now if u reset or switch off the isp modem then again pppoe connection drops but as soon as the isp modem is up again, pppoe goes in a infinite reconnection loop and wont reconnect till u reboot pfsense, what i think is when the isp modem is rebooted, it keeps its network port is some sort of state which just keeps pppoe in the reconnection loop or there is some if and else in mpd coding which detects different states and accordingly attempts a reconenct which while rebooting is different and while reconnection is different.

    more ppl as me might almost contribute to this but bear in mind, the logs dont yield much so some more advanced debug method is required, i can provide access to my PC and box using dialup connection which some1 can login into it and try to see what happens behind the scene with mpd when such a scenario is recreated



  • I would accept to diagnose this with your bounty but need access to your system and you on place to be able to reproduce this 🙂



  • one thing i forgot to mention is my dialup connection etc also run on that fibre optic modem provided by the isp/telephone company so even if i connect using dialup and replicate the issue by turning off the isp modem then my dialup connection would also die and u would loose connection.
    let me try to find some other way to be connected to the internet and still be able to give ua ccess and replicate the issue.

    access to my pc and the firewall i can provide using radmin or teamviewer etc



  • cracking neighbours wifi password to remain connected to the internet while replicating issue, ill message back soon once im ready



  • im ready now, how do i contact u and provide access to my PC?



  • can we do it now?



  • diff –git a/etc/inc/interfaces.inc b/etc/inc/interfaces.inc
    index 679e347…ce9156a 100644
    — a/etc/inc/interfaces.inc
    +++ b/etc/inc/interfaces.inc
    @@ -1612,6 +1612,14 @@ EOD;
                            setup_pppoe_reset_file($ppp[‘if’]);
            }

    +      /* sleep until interface is up - or 30 seconds, whichever comes first */
    +      for ($count = 0; $count < 30; $count++) {
    +              if(file_exists("{$g[‘tmp_path’]}/wanup")) {
    +                      break;
    +              }
    +              sleep(1);
    +      }

    return 1;
    }

    Can you please test these patch on your systems?



  • here r some of the results, below logs r from ppp

    unplug cable and reconnect after 30seconds, wan ip changes on reconnect and auto reconeccts fine

    
    Sep 22 13:02:52 	ppp: [wan_link0] Link: DOWN event
    Sep 22 13:02:52 	ppp: [wan_link0] LCP: Down event
    Sep 22 13:02:52 	ppp: [wan_link0] Link: reconnection attempt 12 in 4 seconds
    Sep 22 13:02:56 	ppp: [wan_link0] Link: reconnection attempt 12
    Sep 22 13:02:56 	ppp: [wan_link0] PPPoE: Connecting to ''
    Sep 22 13:02:56 	ppp: PPPoE: rec'd ACNAME "WE1"
    Sep 22 13:03:03 	ppp: Multi-link PPP daemon for FreeBSD
    Sep 22 13:03:03 	ppp:
    Sep 22 13:03:03 	ppp: process 39410 started, version 5.5 (root@FreeBSD_8.0_pfSense_2.0-snaps.pfsense.org 13:56 11-Aug-2011)
    Sep 22 13:03:03 	ppp: caught fatal signal term
    Sep 22 13:03:03 	ppp: [wan] IFACE: Close event
    Sep 22 13:03:03 	ppp: [wan] IPCP: Close event
    Sep 22 13:03:03 	ppp: waiting for process 8830 to die...
    Sep 22 13:03:05 	ppp: [wan_link0] PPPoE connection timeout after 9 seconds
    Sep 22 13:03:05 	ppp: [wan_link0] Link: DOWN event
    Sep 22 13:03:05 	ppp: [wan_link0] Link: giving up after 12 reconnection attempts
    Sep 22 13:03:05 	ppp: [wan_link0] LCP: Close event
    Sep 22 13:03:05 	ppp: [wan_link0] LCP: state change Starting --> Initial
    Sep 22 13:03:05 	ppp: [wan_link0] LCP: LayerFinish
    Sep 22 13:03:05 	ppp: [wan_link0] LCP: Down event
    Sep 22 13:03:05 	ppp: [wan] Bundle: Shutdown
    Sep 22 13:03:05 	ppp: [wan_link0] Link: Shutdown
    Sep 22 13:03:05 	ppp: process 8830 terminated
    Sep 22 13:03:05 	ppp: waiting for process 8830 to die...
    Sep 22 13:03:05 	ppp: web: web is not running
    Sep 22 13:03:05 	ppp: [wan] Bundle: Interface ng0 created
    Sep 22 13:03:05 	ppp: [wan_link0] Link: OPEN event
    Sep 22 13:03:05 	ppp: [wan_link0] LCP: Open event
    Sep 22 13:03:05 	ppp: [wan_link0] LCP: state change Initial --> Starting
    Sep 22 13:03:05 	ppp: [wan_link0] LCP: LayerStart
    Sep 22 13:03:05 	ppp: [wan_link0] PPPoE: Connecting to ''
    Sep 22 13:03:06 	ppp: PPPoE: rec'd ACNAME "WE1"
    Sep 22 13:03:15 	ppp: [wan_link0] PPPoE connection timeout after 9 seconds
    Sep 22 13:03:15 	ppp: [wan_link0] Link: DOWN event
    Sep 22 13:03:15 	ppp: [wan_link0] LCP: Down event
    Sep 22 13:03:15 	ppp: [wan_link0] Link: reconnection attempt 1 in 1 seconds
    Sep 22 13:03:16 	ppp: [wan_link0] Link: reconnection attempt 1
    Sep 22 13:03:16 	ppp: [wan_link0] PPPoE: Connecting to ''
    Sep 22 13:03:16 	ppp: PPPoE: rec'd ACNAME "WE1"
    Sep 22 13:03:25 	ppp: [wan_link0] PPPoE connection timeout after 9 seconds
    Sep 22 13:03:25 	ppp: [wan_link0] Link: DOWN event
    Sep 22 13:03:25 	ppp: [wan_link0] LCP: Down event
    Sep 22 13:03:25 	ppp: [wan_link0] Link: reconnection attempt 2 in 3 seconds
    Sep 22 13:03:28 	ppp: [wan_link0] Link: reconnection attempt 2
    Sep 22 13:03:28 	ppp: [wan_link0] PPPoE: Connecting to ''
    Sep 22 13:03:28 	ppp: PPPoE: rec'd ACNAME "WE1"
    Sep 22 13:03:37 	ppp: [wan_link0] PPPoE connection timeout after 9 seconds
    Sep 22 13:03:37 	ppp: [wan_link0] Link: DOWN event
    Sep 22 13:03:37 	ppp: [wan_link0] LCP: Down event
    Sep 22 13:03:37 	ppp: [wan_link0] Link: reconnection attempt 3 in 3 seconds
    ....
    Sep 22 13:06:52 	ppp: [wan_link0] PPPoE: Connecting to ''
    Sep 22 13:07:01 	ppp: [wan_link0] PPPoE connection timeout after 9 seconds
    Sep 22 13:07:01 	ppp: [wan_link0] Link: DOWN event
    Sep 22 13:07:01 	ppp: [wan_link0] LCP: Down event
    Sep 22 13:07:01 	ppp: [wan_link0] Link: reconnection attempt 4 in 2 seconds
    Sep 22 13:07:03 	ppp: [wan_link0] Link: reconnection attempt 4
    Sep 22 13:07:03 	ppp: [wan_link0] PPPoE: Connecting to ''
    Sep 22 13:07:12 	ppp: [wan_link0] PPPoE connection timeout after 9 seconds
    Sep 22 13:07:12 	ppp: [wan_link0] Link: DOWN event
    Sep 22 13:07:12 	ppp: [wan_link0] LCP: Down event
    Sep 22 13:07:12 	ppp: [wan_link0] Link: reconnection attempt 5 in 1 seconds
    Sep 22 13:07:13 	ppp: [wan_link0] Link: reconnection attempt 5
    Sep 22 13:07:13 	ppp: [wan_link0] PPPoE: Connecting to ''
    Sep 22 13:07:22 	ppp: [wan_link0] PPPoE connection timeout after 9 seconds
    Sep 22 13:07:22 	ppp: [wan_link0] Link: DOWN event
    Sep 22 13:07:22 	ppp: [wan_link0] LCP: Down event
    Sep 22 13:07:22 	ppp: [wan_link0] Link: reconnection attempt 6 in 1 seconds
    Sep 22 13:07:23 	ppp: [wan_link0] Link: reconnection attempt 6
    Sep 22 13:07:23 	ppp: [wan_link0] PPPoE: Connecting to ''
    Sep 22 13:07:32 	ppp: [wan_link0] PPPoE connection timeout after 9 seconds
    Sep 22 13:07:32 	ppp: [wan_link0] Link: DOWN event
    Sep 22 13:07:32 	ppp: [wan_link0] LCP: Down event
    Sep 22 13:07:32 	ppp: [wan_link0] Link: reconnection attempt 7 in 1 seconds
    Sep 22 13:07:33 	ppp: [wan_link0] Link: reconnection attempt 7
    Sep 22 13:07:33 	ppp: [wan_link0] PPPoE: Connecting to ''
    Sep 22 13:07:42 	ppp: [wan_link0] PPPoE connection timeout after 9 seconds
    Sep 22 13:07:42 	ppp: [wan_link0] Link: DOWN event
    Sep 22 13:07:42 	ppp: [wan_link0] LCP: Down event
    Sep 22 13:07:42 	ppp: [wan_link0] Link: reconnection attempt 8 in 4 seconds
    Sep 22 13:07:46 	ppp: [wan_link0] Link: reconnection attempt 8
    Sep 22 13:07:46 	ppp: [wan_link0] PPPoE: Connecting to ''
    Sep 22 13:07:46 	ppp: PPPoE: rec'd ACNAME "WE1"
    Sep 22 13:07:55 	ppp: [wan_link0] PPPoE connection timeout after 9 seconds
    Sep 22 13:07:55 	ppp: [wan_link0] Link: DOWN event
    Sep 22 13:07:55 	ppp: [wan_link0] LCP: Down event
    Sep 22 13:07:55 	ppp: [wan_link0] Link: reconnection attempt 9 in 1 seconds
    Sep 22 13:07:56 	ppp: [wan_link0] Link: reconnection attempt 9
    Sep 22 13:07:56 	ppp: [wan_link0] PPPoE: Connecting to ''
    Sep 22 13:07:56 	ppp: PPPoE: rec'd ACNAME "WE1"
    Sep 22 13:08:05 	ppp: [wan_link0] PPPoE connection timeout after 9 seconds
    Sep 22 13:08:05 	ppp: [wan_link0] Link: DOWN event
    Sep 22 13:08:05 	ppp: [wan_link0] LCP: Down event
    Sep 22 13:08:05 	ppp: [wan_link0] Link: reconnection attempt 10 in 2 seconds
    Sep 22 13:08:07 	ppp: [wan_link0] Link: reconnection attempt 10
    Sep 22 13:08:07 	ppp: [wan_link0] PPPoE: Connecting to ''
    Sep 22 13:08:07 	ppp: PPPoE: rec'd ACNAME "WE1"
    Sep 22 13:08:53 	ppp: [wan_link0] PPPoE: connection successful
    Sep 22 13:08:53 	ppp: [wan_link0] Link: UP event
    Sep 22 13:08:53 	ppp: [wan_link0] LCP: Up event
    Sep 22 13:08:53 	ppp: [wan_link0] LCP: state change Starting --> Req-Sent
    Sep 22 13:08:53 	ppp: [wan_link0] LCP: SendConfigReq #4
    Sep 22 13:08:53 	ppp: [wan_link0] PROTOCOMP
    Sep 22 13:08:53 	ppp: [wan_link0] MRU 1492
    Sep 22 13:08:53 	ppp: [wan_link0] MAGICNUM 9ecd1a58
    Sep 22 13:08:53 	ppp: [wan_link0] LCP: rec'd Configure Request #88 (Req-Sent)
    Sep 22 13:08:53 	ppp: [wan_link0] MRU 1492
    Sep 22 13:08:53 	ppp: [wan_link0] AUTHPROTO PAP
    Sep 22 13:08:53 	ppp: [wan_link0] MAGICNUM 6fd061fb
    Sep 22 13:08:53 	ppp: [wan_link0] LCP: SendConfigAck #88
    Sep 22 13:08:53 	ppp: [wan_link0] MRU 1492
    Sep 22 13:08:53 	ppp: [wan_link0] AUTHPROTO PAP
    Sep 22 13:08:53 	ppp: [wan_link0] MAGICNUM 6fd061fb
    Sep 22 13:08:53 	ppp: [wan_link0] LCP: state change Req-Sent --> Ack-Sent
    Sep 22 13:08:53 	ppp: [wan_link0] LCP: rec'd Configure Ack #4 (Ack-Sent)
    Sep 22 13:08:53 	ppp: [wan_link0] PROTOCOMP
    Sep 22 13:08:53 	ppp: [wan_link0] MRU 1492
    Sep 22 13:08:53 	ppp: [wan_link0] MAGICNUM 9ecd1a58
    Sep 22 13:08:53 	ppp: [wan_link0] LCP: state change Ack-Sent --> Opened
    Sep 22 13:08:53 	ppp: [wan_link0] LCP: auth: peer wants PAP, I want nothing
    Sep 22 13:08:53 	ppp: [wan_link0] PAP: using authname "xbipin"
    Sep 22 13:08:53 	ppp: [wan_link0] PAP: sending REQUEST #1 len: 20
    Sep 22 13:08:53 	ppp: [wan_link0] LCP: LayerUp
    Sep 22 13:08:55 	ppp: [wan_link0] PAP: using authname "xbipin"
    Sep 22 13:08:55 	ppp: [wan_link0] PAP: sending REQUEST #2 len: 20
    Sep 22 13:08:59 	ppp: [wan_link0] PAP: using authname "xbipin"
    Sep 22 13:08:59 	ppp: [wan_link0] PAP: sending REQUEST #4 len: 20
    Sep 22 13:09:01 	ppp: [wan_link0] PAP: rec'd ACK #4 len: 5
    Sep 22 13:09:01 	ppp: [wan_link0] LCP: authorization successful
    Sep 22 13:09:01 	ppp: [wan_link0] Link: Matched action 'bundle "wan" ""'
    Sep 22 13:09:01 	ppp: [wan_link0] Link: Join bundle "wan"
    Sep 22 13:09:01 	ppp: [wan] Bundle: Status update: up 1 link, total bandwidth 64000 bps
    Sep 22 13:09:01 	ppp: [wan] IPCP: Open event
    Sep 22 13:09:01 	ppp: [wan] IPCP: state change Initial --> Starting
    Sep 22 13:09:01 	ppp: [wan] IPCP: LayerStart
    Sep 22 13:09:01 	ppp: [wan] IPCP: Up event
    Sep 22 13:09:01 	ppp: [wan] IPCP: state change Starting --> Req-Sent
    Sep 22 13:09:01 	ppp: [wan] IPCP: SendConfigReq #4
    Sep 22 13:09:01 	ppp: [wan] IPADDR 0.0.0.0
    Sep 22 13:09:01 	ppp: [wan] IPCP: rec'd Configure Nak #4 (Req-Sent)
    Sep 22 13:09:01 	ppp: [wan] IPADDR 92.99.131.139
    Sep 22 13:09:01 	ppp: [wan] 92.99.131.139 is OK
    Sep 22 13:09:01 	ppp: [wan] IPCP: SendConfigReq #5
    Sep 22 13:09:01 	ppp: [wan] IPADDR 92.99.131.139
    Sep 22 13:09:01 	ppp: [wan] IPCP: rec'd Configure Ack #5 (Req-Sent)
    Sep 22 13:09:01 	ppp: [wan] IPADDR 92.99.131.139
    Sep 22 13:09:01 	ppp: [wan] IPCP: state change Req-Sent --> Ack-Rcvd
    Sep 22 13:09:01 	ppp: [wan] IPCP: rec'd Configure Request #210 (Ack-Rcvd)
    Sep 22 13:09:01 	ppp: [wan] IPADDR 195.229.252.27
    Sep 22 13:09:01 	ppp: [wan] 195.229.252.27 is OK
    Sep 22 13:09:01 	ppp: [wan] IPCP: SendConfigAck #210
    Sep 22 13:09:01 	ppp: [wan] IPADDR 195.229.252.27
    Sep 22 13:09:01 	ppp: [wan] IPCP: state change Ack-Rcvd --> Opened
    Sep 22 13:09:01 	ppp: [wan] IPCP: LayerUp
    Sep 22 13:09:01 	ppp: [wan] 92.99.131.139 -> 195.229.252.27
    Sep 22 13:09:01 	ppp: [wan] IFACE: Up event
    
    

    unplug cable and reconnect in less than 30seconds, wan ip remains same at first then later changes and reconnects fine

    
    Sep 22 13:20:35 	ppp: [wan_link0] LCP: no reply to 1 echo request(s)
    Sep 22 13:21:45 	ppp: [wan_link0] LCP: no reply to 1 echo request(s)
    Sep 22 13:21:45 	ppp: [wan_link0] LCP: no reply to 2 echo request(s)
    Sep 22 13:21:55 	ppp: [wan_link0] LCP: no reply to 3 echo request(s)
    ...
    Sep 22 13:48:20 	ppp: [wan_link0] PROTOCOMP
    Sep 22 13:48:20 	ppp: [wan_link0] MRU 1492
    Sep 22 13:48:20 	ppp: [wan_link0] MAGICNUM a59b33b8
    Sep 22 13:48:21 	ppp: [wan_link0] LCP: rec'd Configure Request #67 (Req-Sent)
    Sep 22 13:48:21 	ppp: [wan_link0] MRU 1492
    Sep 22 13:48:21 	ppp: [wan_link0] AUTHPROTO PAP
    Sep 22 13:48:21 	ppp: [wan_link0] MAGICNUM 35150c1e
    Sep 22 13:48:21 	ppp: [wan_link0] LCP: SendConfigAck #67
    Sep 22 13:48:21 	ppp: [wan_link0] MRU 1492
    Sep 22 13:48:21 	ppp: [wan_link0] AUTHPROTO PAP
    Sep 22 13:48:21 	ppp: [wan_link0] MAGICNUM 35150c1e
    Sep 22 13:48:21 	ppp: [wan_link0] LCP: state change Req-Sent --> Ack-Sent
    Sep 22 13:48:21 	ppp: [wan_link0] LCP: rec'd Configure Ack #7 (Ack-Sent)
    Sep 22 13:48:21 	ppp: [wan_link0] PROTOCOMP
    Sep 22 13:48:21 	ppp: [wan_link0] MRU 1492
    Sep 22 13:48:21 	ppp: [wan_link0] MAGICNUM a59b33b8
    Sep 22 13:48:21 	ppp: [wan_link0] LCP: state change Ack-Sent --> Opened
    Sep 22 13:48:21 	ppp: [wan_link0] LCP: auth: peer wants PAP, I want nothing
    Sep 22 13:48:21 	ppp: [wan_link0] PAP: using authname "xbipin"
    Sep 22 13:48:21 	ppp: [wan_link0] PAP: sending REQUEST #1 len: 20
    Sep 22 13:48:21 	ppp: [wan_link0] LCP: LayerUp
    Sep 22 13:48:21 	ppp: [wan_link0] PAP: rec'd ACK #1 len: 5
    Sep 22 13:48:21 	ppp: [wan_link0] LCP: authorization successful
    Sep 22 13:48:21 	ppp: [wan_link0] Link: Matched action 'bundle "wan" ""'
    Sep 22 13:48:21 	ppp: [wan_link0] Link: Join bundle "wan"
    Sep 22 13:48:21 	ppp: [wan] Bundle: Status update: up 1 link, total bandwidth 64000 bps
    Sep 22 13:48:21 	ppp: [wan] IPCP: Open event
    Sep 22 13:48:21 	ppp: [wan] IPCP: state change Initial --> Starting
    Sep 22 13:48:21 	ppp: [wan] IPCP: LayerStart
    Sep 22 13:48:21 	ppp: [wan] IPCP: Up event
    Sep 22 13:48:21 	ppp: [wan] IPCP: state change Starting --> Req-Sent
    Sep 22 13:48:21 	ppp: [wan] IPCP: SendConfigReq #7
    Sep 22 13:48:21 	ppp: [wan] IPADDR 0.0.0.0
    Sep 22 13:48:21 	ppp: [wan] IPCP: rec'd Configure Nak #7 (Req-Sent)
    Sep 22 13:48:21 	ppp: [wan] IPADDR 92.99.205.85
    Sep 22 13:48:21 	ppp: [wan] 92.99.205.85 is OK
    Sep 22 13:48:21 	ppp: [wan] IPCP: SendConfigReq #8
    Sep 22 13:48:21 	ppp: [wan] IPADDR 92.99.205.85
    Sep 22 13:48:21 	ppp: [wan] IPCP: rec'd Configure Ack #8 (Req-Sent)
    Sep 22 13:48:21 	ppp: [wan] IPADDR 92.99.205.85
    Sep 22 13:48:21 	ppp: [wan] IPCP: state change Req-Sent --> Ack-Rcvd
    Sep 22 13:48:21 	ppp: [wan] IPCP: rec'd Configure Request #245 (Ack-Rcvd)
    Sep 22 13:48:21 	ppp: [wan] IPADDR 195.229.252.27
    Sep 22 13:48:21 	ppp: [wan] 195.229.252.27 is OK
    Sep 22 13:48:21 	ppp: [wan] IPCP: SendConfigAck #245
    Sep 22 13:48:21 	ppp: [wan] IPADDR 195.229.252.27
    Sep 22 13:48:21 	ppp: [wan] IPCP: state change Ack-Rcvd --> Opened
    Sep 22 13:48:21 	ppp: [wan] IPCP: LayerUp
    Sep 22 13:48:21 	ppp: [wan] 92.99.205.85 -> 195.229.252.27
    Sep 22 13:48:21 	ppp: [wan] IFACE: Up event
    
    

    fibre optic modem from isp reset or power plug pulled and then after some time repowered but pf doesnt reconnect, log below

    
    Sep 22 13:52:31 	ppp: [wan_link0] LCP: no reply to 1 echo request(s)
    Sep 22 13:52:41 	ppp: [wan_link0] LCP: no reply to 2 echo request(s)
    Sep 22 13:52:51 	ppp: [wan_link0] LCP: no reply to 3 echo request(s)
    Sep 22 13:53:01 	ppp: [wan_link0] LCP: no reply to 4 echo request(s)
    Sep 22 13:53:11 	ppp: [wan_link0] LCP: no reply to 5 echo request(s)
    Sep 22 13:53:11 	ppp: [wan_link0] LCP: peer not responding to echo requests
    Sep 22 13:53:11 	ppp: [wan_link0] LCP: state change Opened --> Stopping
    Sep 22 13:53:11 	ppp: [wan_link0] Link: Leave bundle "wan"
    Sep 22 13:53:11 	ppp: [wan] Bundle: Status update: up 0 links, total bandwidth 9600 bps
    Sep 22 13:53:11 	ppp: [wan] IPCP: Close event
    Sep 22 13:53:11 	ppp: [wan] IPCP: state change Opened --> Closing
    Sep 22 13:53:11 	ppp: [wan] IPCP: SendTerminateReq #9
    Sep 22 13:53:11 	ppp: [wan] IPCP: LayerDown
    Sep 22 13:53:11 	ppp: [wan] IFACE: Down event
    Sep 22 13:53:11 	ppp: [wan] IPCP: Down event
    Sep 22 13:53:11 	ppp: [wan] IPCP: LayerFinish
    Sep 22 13:53:11 	ppp: [wan] Bundle: No NCPs left. Closing links...
    Sep 22 13:53:11 	ppp: [wan] IPCP: state change Closing --> Initial
    Sep 22 13:53:11 	ppp: [wan_link0] LCP: SendTerminateReq #8
    Sep 22 13:53:11 	ppp: [wan_link0] LCP: LayerDown
    Sep 22 13:53:13 	ppp: [wan_link0] LCP: SendTerminateReq #9
    Sep 22 13:53:15 	ppp: [wan_link0] LCP: state change Stopping --> Stopped
    Sep 22 13:53:15 	ppp: [wan_link0] LCP: LayerFinish
    Sep 22 13:53:15 	ppp: [wan_link0] PPPoE: connection closed
    Sep 22 13:53:15 	ppp: [wan_link0] Link: DOWN event
    Sep 22 13:53:15 	ppp: [wan_link0] LCP: Down event
    Sep 22 13:53:15 	ppp: [wan_link0] LCP: state change Stopped --> Starting
    Sep 22 13:53:15 	ppp: [wan_link0] LCP: LayerStart
    Sep 22 13:53:15 	ppp: [wan_link0] Link: reconnection attempt 1 in 1 seconds
    Sep 22 13:53:16 	ppp: [wan_link0] Link: reconnection attempt 1
    Sep 22 13:53:16 	ppp: [wan_link0] PPPoE: Connecting to ''
    Sep 22 13:53:25 	ppp: [wan_link0] PPPoE connection timeout after 9 seconds
    Sep 22 13:53:25 	ppp: [wan_link0] Link: DOWN event
    Sep 22 13:53:25 	ppp: [wan_link0] LCP: Down event
    Sep 22 13:53:25 	ppp: [wan_link0] Link: reconnection attempt 2 in 2 seconds
    Sep 22 13:53:27 	ppp: [wan_link0] Link: reconnection attempt 2
    Sep 22 13:53:27 	ppp: [wan_link0] PPPoE: Connecting to ''
    Sep 22 13:53:36 	ppp: [wan_link0] PPPoE connection timeout after 9 seconds
    Sep 22 13:53:36 	ppp: [wan_link0] Link: DOWN event
    Sep 22 13:53:36 	ppp: [wan_link0] LCP: Down event
    Sep 22 13:53:36 	ppp: [wan_link0] Link: reconnection attempt 3 in 3 seconds
    Sep 22 13:53:39 	ppp: [wan_link0] Link: reconnection attempt 3
    Sep 22 13:53:39 	ppp: [wan_link0] PPPoE: Connecting to ''
    Sep 22 13:53:48 	ppp: [wan_link0] PPPoE connection timeout after 9 seconds
    Sep 22 13:53:48 	ppp: [wan_link0] Link: DOWN event
    Sep 22 13:53:48 	ppp: [wan_link0] LCP: Down event
    Sep 22 13:53:48 	ppp: [wan_link0] Link: reconnection attempt 4 in 2 seconds
    Sep 22 13:53:50 	ppp: [wan_link0] Link: reconnection attempt 4
    Sep 22 13:53:50 	ppp: [wan_link0] PPPoE: Connecting to ''
    Sep 22 13:53:59 	ppp: [wan_link0] PPPoE connection timeout after 9 seconds
    Sep 22 13:53:59 	ppp: [wan_link0] Link: DOWN event
    Sep 22 13:53:59 	ppp: [wan_link0] LCP: Down event
    Sep 22 13:53:59 	ppp: [wan_link0] Link: reconnection attempt 5 in 1 seconds
    Sep 22 13:54:00 	ppp: [wan_link0] Link: reconnection attempt 5
    Sep 22 13:54:00 	ppp: [wan_link0] PPPoE: Connecting to ''
    Sep 22 13:54:09 	ppp: [wan_link0] PPPoE connection timeout after 9 seconds
    Sep 22 13:54:09 	ppp: [wan_link0] Link: DOWN event
    Sep 22 13:54:09 	ppp: [wan_link0] LCP: Down event
    Sep 22 13:54:09 	ppp: [wan_link0] Link: reconnection attempt 6 in 3 seconds
    Sep 22 13:54:12 	ppp: [wan_link0] Link: reconnection attempt 6
    Sep 22 13:54:12 	ppp: [wan_link0] PPPoE: Connecting to ''
    
    


  • in summary, resetting isp modem doesnt make pppoe reconnect, problem still persists



  • any luck?



  • The logs displayed a couple of replies back suggest the remote PPP is not responding. Since this seems to be fairly easily reproduced I suggests you make it happen while you have a packet trace running so you can see if there is response from the ISP. Is there any response from the ISP’s end? If not, call their technical support to report the problem.



  • do i run the below command with itnerface as pppoe0 or vr1 ?

    tcpdump -i $interface -s 0 -vvvX -w /tmp/pcap.capture



  • command run with interface as pppoe0 and replicated a isp modem reset and complete endless loop for a while for pf reconnection attempt
    file name - pcap.capture1

    command run with interface as vr1 and replicated a isp modem reset and complete endless loop for a while for pf reconnection attempt
    file name - pcap.capture2

    the cable from the isp modem to pf if i put in my PC then the LAN status always shows limited connectivity and no IP from DHCP untill a pppoe connection is dialed out

    all standard routers such as dlink, aztec etc sold in this region work fine when u replicate the same situation so i wonder how do they reconnect fine even if u reset or unplug and replug the isp modem



  • the strange thing is, suppose i remove the wan cable going from my isp modem to pfsense and reboot pfsense then once its done it doesnt have any internet connection and no wan ip but as soon as i plug the cable from my isp modem to pfsense, in just one attempt it connects and remains connected.

    so i guess the issue is mpd would need the vr1 used for wan to do down and then replugging it would get it up and then mpd would dial out perfectly fine but if the isp modem was just reset then the port has the power on so i guess it doesn’t go down completely and then reconnection attempt keeps failing. i mayb wrong on the above but at least on a pfsense reboot everything works fine and even on a cable unplug and replug also works fine but on a modem reset only it doesn’t work or mayb if the isp modem hanged or dropped the connection then also it would connect but i havent been able to do that.



  • can anything be done to solve this?



  • Sorry, I haven’t had a lot of time to look into this.

    I have looked at your packet captures. Unfortunately they don’t show the PPP control packets. Can you provide another set with the capture interface being the physical device used for the PPP link rather than the PPP link? For example, if pppoe0 uses physical interface vr1 I would like the capture on interface vr1 rather than pppoe0.

    capture1 initially shows pings and replies then just pings (no replies). No ppp control packets.

    capture2 just looks like “normal” traffic: no PPP control packets shown and no obvious sign of a “down” link. (I expected to see repeated PPP initalisation attempts.) Capture2 timestamps go from 18:57:31.x to 18:57:42.x, about 11 seconds. Your previously posted log of a failed reinitialisation covers a time span of nearly two minutes. Are you sure you provided a capture taken when mpd was reporting repeated initialisation attempts?

    Your previous posts have repeated mentioned a modem reset. What is a modem reset and (since it appears to cause so much grief) why do you do it?



  • i just ran the command given to me for both pppoe0 and vr1 and when i said mpd going in reconenct loop, that actually i see from the web gui but i also fail to understand y no pppoe control packets r seen on the trace related to vr1, i hope its the right command im running.

    the issue is just not modem reset but suppose if its goes down or drops an active connection or it has a firmware update and reboots or even in pfsense i set periodic reset for pppoe, in all these situations it never reconnects untill i reboot pfsense so.

    ill again run a trace for vr1 and send it



  • here is another capture, its the same, once the isp modem is reset the packet count never goes ahead inspite of mpd retrying to conect, correct me if im wrong, below is the command i run

    tcpdump -i vr1 -s 0 -vvvX -w /tmp/pcap.capture

    capture can be downloaded from
    http://www.mediafire.com/?41s858ze4bri7c9



  • @xbipin:

    correct me if im wrong, below is the command i run

    tcpdump -i vr1 -s 0 -vvvX -w /tmp/pcap.capture

    Looks fine to me though -vvvX seems to apply just to decoding and displaying captured data.

    @xbipin:

    here is another capture, its the same, once the isp modem is reset the packet count never goes ahead inspite of mpd retrying to conect

    Capture ran from 16:46:56.457199 to 16:47:16.647419 and shows pings and responses for the whole duration (about 20 seconds). Perhaps you ran the capture for much longer than 20 seconds and there was no traffic after the last entry. This doesn’t seem consistent with mpd’s claim to be making reconnection attempts.



  • the capture was running for more than 2-3mins and when i say no traffic after last entry, i meant once i reset the modem, the last captured packet was before that and after that inspite of mpd showing reconenct attempts under logs, no packets control or any other appear in the trace so mayb mpd just keeps saying its reconnecting but no actual attempt is made or mayb the capture doesnt take the ppoe control packets in the trace at all.

    anyways ill run the trace again for about 5mins now but im sure the capture wont have any packets in them related to reconnect attempts



  • i ran the trace and its the same, it takes about 20secs for me to start the trace and then reset the modem and once done, for the next 10mins also no new packets in the capture



  • for al alternative approach, i took the wan wire and plugged it into my windows PC and started wireshark and then first created a pppoe connection and dialed it and all fine and then reset the  modem and windows too wont redial at all till the LAN card is disabled and enabled again and then the same connection redialed, i hope this trace will help as it lists pppoe control packets as well

    http://www.mediafire.com/?sp6n1weermra3y8



  • what i noticed from the trace was after modem reset the PC sends a PADI and the server replies with PADO then PC sends PADR but then the server for some reason doesnt send the PADS and to only make this work, the LAN card needs to be disabled and reenabled so guess one solution between reconnection request sent by mpd would be to actually disable the port first then enable it and then dialout, no idea how but the older mpd v4 used to and still does work like a charm but for that i would have to revert back to pfsense 1.2.3



  • any suggestions?



  • Ermal is probably away, since according to this, both he and cmb will be doing a presentation at EuroBSDCon11 on 6-Oct-2011.

    Have you contacted mpd’s developers at http://sourceforge.net/projects/mpd/ about this?



  • no i havent checked with the mpd developers, it would be like repeating a year long story from start 🙂



  • no progress yet



  • Can you please re-upload the last 2 capture files, they have been removed from mediafire.



  • you can check pptp connection via icmp and if ping fails x times, restart your pptp connection.
    It could be at cron or included in the patch that emal sent in this tread.

    I have a similar situation with cisco vpn and this check solved my problem.



  • i would like to mention again, restarting etc doesnt solve it coz even if i manually stop and start it, it wont connect, its something in the pppoe protocol and for some reason the modem doesnt send back PADS which its supposed to

    Insert Quote
    what i noticed from the trace was after modem reset the PC sends a PADI and the server replies with PADO then PC sends PADR but then the server for some reason doesnt send the PADS and to only make this work, the LAN card needs to be disabled and reenabled so guess one solution between reconnection request sent by mpd would be to actually disable the port first then enable it and then dialout, no idea how but the older mpd v4 used to and still does work like a charm but for that i would have to revert back to pfsense 1.2.3



  • here is the last trace link
    http://www.mediafire.com/?v3o0wbz4e74cwqq



  • heres another trace from the vr1 interface, changes i made were
    set a custom reset period
    change service name under WAN to WE1 (no idea if this makes a difference or no)

    purpose of trace was to test if pppoe reconnects fine on a custom reset period set in pfsense and result was it did reconnect fine

    command run to trace was
    tcpdump -i vr1 -s 0 -vvvX -w /tmp/pcap.capture

    trace file
    http://www.mediafire.com/?osabfdk0189hgai



  • the problem in running the same above command and taking a trace is that once the isp modem is switched off or reset, all activity stops on vr1 and so no more packets r traced, even closing the trace and rerunning the command doesnt yield any more packets at all so which could mean a trace actually stops if the port is switched off or reset and even once the modem has come back online, rerunning the trace shows no packets what so everso this could be the actual issue as the web gui keeps showing reconnection attempts but the trace doesnt yield any packet at all so it could mean if the vr1 port is prematurely brought down then even if it gets up, mpd isnt able to reuse it at all coz in the previous trace it showed that a custom reset brings the interface down and up again successfully.



  • I am looking at the trace with 138.943 Bytes (the smaller one of the last 2 traces).

    What I can see from that is that the PPPoE Server/BRAS is NOT aware that the session has been brought down. The modem has been reset at frame 528 i guess, where we can see a PADT. We have no LCP Termination request and Termination Ack, probably because the modem is booting at that time. Also that PADT probably never reached the PPPoE Server on the other side.

    So while the Firewall/PC is already aware that the session is down and trying to reestablish the PPPoE connection, the BRAS is not, having a zombie pppoe session active. We can see that in frame 588 and 649, because the BRAS is still sending LCP echos for the old session.

    So what? The BRAS or intermediate access-switches probably have some DDOS countermeasures configured, which allow only 1 session per mac (or modem or port or whatever), and because the session is still up, flood protection hoped in and the PADR is ignored.

    It should be only a matter of time until the BRAS considers the zombie session to be stale, discard that session and let you reestablish the connection.

    Did you try to let the Firewall run for 10 - 15 minutes and see if it changed anything?
    Are you sure that you fix this by downgrading your FW, or may it be that your provider has changed something on their network the same period you upgraded your FW?
    You told us that you have the same problem when terminating the PPPoE connection on the PC. Are you using mpd to establish the connection on your PC?

    What we need is a complete trace that includes everything in a larger timespan.

    You should put a switch/hub between the firewall and the modem, this way the port on the firewall stays up, and the capture is still running. Also we need at least 10 minutes of connection uptime, only then reset the modem, and let the capture running for another 10 - 15 minutes.

    Only that way we can understand the whole context of the Control Session packets.

    If you want to remove your own internet traffic from the dump, you can open the capture in wireshark, set the display filter to:```
    pppoed || (pppoes && ppp.protocol == 0xc021)



  • I believe I am experiencing the same issue*. If Ermal** is willing, I can provide him a live system for troubleshooting/testing with ssh and/or web access through a separate WAN. This is a production system, so there are some conditions:

    1. I must be notified and present at all times when you are logged in.
    2. The main WAN can only be down from 4-6 am Mountain time. If I have to reflash the system and restore my config, that’s fine, but it will be happening by 6 am.

    PM me if you want to take me up on it.

    *http://redmine.pfsense.org/issues/1943
    **If somebody besides Ermal wants to take this on then you’ll need somebody that I trust to vouch for you.



  • i guess its clear from luky37 's post that the pppoe server doesnt allow more than one session which i think is true in my region coz the isp doesnt allow the same account to reconnect from an alternate location as well.

    ill try connecting the wan through a switch and getting a trace, cant gaurantee it will be for 15mins though but atleast it will capture the events in the link reset situation.

    would it be possible to make pfsense remember the last settings during connection negotiation and once the link is up, send a connection termination packet then restart the whole pppoe protocol?



  • here is the trace with a switch between pf and the isp modem to keep the trace running in spite of modem being reset
    http://www.mediafire.com/?9m8g65a5v975qc1

    it seems true, the modem remembers the last active connection and so doesn’t allow a new connection but a way to over come this was, what i noticed was, once i unplug the cable and then replug it, this in turn tells the modem a link down and then it tells the pppoe server to erase previous connection info due to link down and then once i plug in the cable, pfsense will renegotiate a successful connection (this unplug and replug isn’t part of the trace because i cant keep the connection down too long as its used in production)



  • Are you saying that the modem, in bridge mode, is remembering an active session and preventing a new one? If that’s the case, why does rebooting pfsense re-establish the connection? There is a switch between my modems and pfsense, so the modem will never see the link as down.



  • and to answer previous questions:

    • i have left the firewall on for more than 60mins in the past but it never reconnects, reason is because no switch present in between so once the port is in a half dead state, no packets reach between firewall and the modem because its never able to recover from this state which was proved by trace also without the switch. bringing down the port to off and then on or unplugging the cable and replugging it would get it back in a working state such that packets would be able to go from firewall to modem.

    • it could be the isp might have changed something but to my knowledge there hasnt been any firmware upgrade till date of the modem or on any side and till almost a 2 months back i had tried the older pf with old mpd and it worked fine

    • on the pc i never used mpd, i just used the windows built in RAS and dial up connection thing

    would it be possible to implement this:
    once link goes down and pfsense starts to go in endless reconnection loop, try about 5 times and if still failed, make the vr1 on the firewall to down state and then after a few secs to up state and then reattempt, keep doing this till the isp modem has come back alive after reset or reboot after which the vr1 down will at least once trigger a connection end on the pppoe server and then next attempt would get it reconnected again.

    OR

    fix the half dead vr1 port state detection on the vr1 on pfsense



  • @clarknova:

    Are you saying that the modem, in bridge mode, is remembering an active session and preventing a new one? If that’s the case, why does rebooting pfsense re-establish the connection? There is a switch between my modems and pfsense, so the modem will never see the link as down.

    the port on the isp modem needs to be brought down by unplugging the cable to make it send a link down to its remote pppoe server then when its brought up again with a replug, then pfsense renegotiates a new connection successfully.

    the part about how its able to reconnect on pfsense boot i seriously don’t understand how that happens now, there definitely is some difference in the way mpd connects on boot and on link loss


 

© Copyright 2002 - 2018 Rubicon Communications, LLC | Privacy Policy