2.0RC MLPPP doesn't work with my provider

eri--

Try with i386 snapshot and please post screenshots from the ppp tab configuration settings.

Epoch

The latest i386 snapshot? I have previously tried the i386 version of RC1 and one of the versions from last week as an i386 build before reloading and putting an amd64 build on the machine.
Also, I assume that I have to reinstall to get a i386 version installed again and that I can't just manually upgrade the firmware after removing packages and clearing out rrd graphs. Am I correct in that assumption?
If so, I can do that in tomorrow and do a bit more testing, as well as posting the requested screenshots. I will also post the mpd_wan.conf that it generates with the username and passwords scrubbed.

chpalmer

@chpalmer:

Are you able to force your mru and mrru in the advanced settings on ppp groups? Or even mtu on your wan interface page?

Hi Epoch: I ask because no matter what I put in these fields they dont seem to take. So I was wondering if it could be related… I just need more time in a day to do more testing on my end...

chpalmer

heres my mpd conf file for comparison in case it helps ya… Settings from the gui do make it here flawlessly for me.

chpalmermlppp.txt

Epoch

I assume that you are having the same issue then. Judging by your MRRU I bet that your provider also uses Cisco hardware, which means that what you set in your advanced settings for MLPPP are being set correctly by pfSense, but they are being rejected/renegotiated when you actually connect to your provider.

I think that if you look in /var/log/ppp.log you will find something that looks like the following, only it will advertise MRU and MRRU as you have set it. My log was sitting at defaults for this last attempt in my log files, though it was set for the correct values previously when it didn't work.

 ppp: Multi-link PPP daemon for FreeBSD
 ppp:  
 ppp: process 48152 started, version 5.5 (root@FreeBSD_8.0_pfSense_2.0-AMD64.snaps.pfsense.org 15:16 25-Apr-2011)
 ppp: web: web is not running
 ppp: [opt1] Bundle: Interface ng0 created
 ppp: [opt1_link0] Link: OPEN event
 ppp: [opt1_link0] LCP: Open event
 ppp: [opt1_link0] LCP: state change Initial --> Starting
 ppp: [opt1_link0] LCP: LayerStart
 ppp: [opt1_link1] Link: OPEN event
 ppp: [opt1_link1] LCP: Open event
 ppp: [opt1_link1] LCP: state change Initial --> Starting
 ppp: [opt1_link1] LCP: LayerStart
 ppp: [opt1_link0] PPPoE: Connecting to '*'
 ppp: [opt1_link1] PPPoE: Connecting to '*'
 ppp: PPPoE: rec'd ACNAME "name"
 ppp: PPPoE: rec'd ACNAME "name"
 ppp: [opt1_link0] PPPoE: connection successful
 ppp: [opt1_link0] Link: UP event
 ppp: [opt1_link0] LCP: Up event
 ppp: [opt1_link0] LCP: state change Starting --> Req-Sent
 ppp: [opt1_link0] LCP: SendConfigReq #1
 ppp: [opt1_link0]   PROTOCOMP
 ppp: [opt1_link0]   MRU 1492
 ppp: [opt1_link0]   MAGICNUM 2c2bbff8
 ppp: [opt1_link0]   MP MRRU 2048
 ppp: [opt1_link0]   ENDPOINTDISC [802.1] YOUR MAC
 ppp: [opt1_link1] PPPoE: connection successful

chpalmer

Actually mine links up and appears ok until I run into mtu issues… ISP blames my router and I am pretty sure its something on their end.

My logs however.. From /diag_logs_ppp.php when I go to var/log/ppp.log filemanager and/or Firefox 4 return a blank page.

But just throwing it out there in case its related some how...

Notice my MRU does not match what I have above.

May 25 17:26:25 ppp: [wan] IPCP: rec'd Configure Request #1 (Req-Sent)
May 25 17:26:25 ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
May 25 17:26:25 ppp: [wan] IPADDR x.x.x.x
May 25 17:26:25 ppp: [wan] x.x.x.xis OK
May 25 17:26:25 ppp: [wan] IPCP: SendConfigAck #1
May 25 17:26:25 ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
May 25 17:26:25 ppp: [wan] IPADDR x.x.x.x
May 25 17:26:25 ppp: [wan] IPCP: state change Req-Sent –> Ack-Sent
May 25 17:26:25 ppp: [wan] IPCP: rec'd Configure Nak #1 (Ack-Sent)
May 25 17:26:25 ppp: [wan] IPADDR x.x.x.x
May 25 17:26:25 ppp: [wan] x.x.x.x is OK
May 25 17:26:25 ppp: [wan] PRIDNS 173.244.96.10
May 25 17:26:25 ppp: [wan] SECDNS 173.244.96.11
May 25 17:26:25 ppp: [wan] IPCP: SendConfigReq #2
May 25 17:26:25 ppp: [wan] IPADDR x.x.x.x
May 25 17:26:25 ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
May 25 17:26:25 ppp: [wan] PRIDNS 173.244.96.10
May 25 17:26:25 ppp: [wan] SECDNS 173.244.96.11
May 25 17:26:25 ppp: [wan_link0] LCP: rec'd Configure Nak #1 (Ack-Sent)
May 25 17:26:25 ppp: [wan_link0] MRU 1492
May 25 17:26:25 ppp: [wan_link0] LCP: SendConfigReq #2
May 25 17:26:25 ppp: [wan_link0] PROTOCOMP
May 25 17:26:25 ppp: [wan_link0] MRU 1492
May 25 17:26:25 ppp: [wan_link0] MAGICNUM b5a81020
May 25 17:26:25 ppp: [wan_link0] MP MRRU 1524
May 25 17:26:25 ppp: [wan_link0] ENDPOINTDISC [802.1] 00 09 5b 8f 1b 71
May 25 17:26:25 ppp: [wan] IPCP: rec'd Configure Ack #2 (Ack-Sent)
May 25 17:26:25 ppp: [wan] IPADDR x.x.x.x
May 25 17:26:25 ppp: [wan] COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
May 25 17:26:25 ppp: [wan] PRIDNS 173.244.96.10
May 25 17:26:25 ppp: [wan] SECDNS 173.244.96.11
May 25 17:26:25 ppp: [wan] IPCP: state change Ack-Sent –> Opened
May 25 17:26:25 ppp: [wan] IPCP: LayerUp
May 25 17:26:25 ppp: [wan] x.x.x.x-> x.x.x.x
May 25 17:26:26 ppp: [wan] IFACE: Up event
May 25 17:26:26 ppp: [wan_link0] LCP: rec'd Configure Ack #2 (Ack-Sent)
May 25 17:26:26 ppp: [wan_link0] PROTOCOMP
May 25 17:26:26 ppp: [wan_link0] MRU 1492
May 25 17:26:26 ppp: [wan_link0] MAGICNUM b5a81020
May 25 17:26:26 ppp: [wan_link0] MP MRRU 1524
May 25 17:26:26 ppp: [wan_link0] ENDPOINTDISC [802.1] 00 09 5b 8f 1b 71
May 25 17:26:26 ppp: [wan_link0] LCP: state change Ack-Sent –> Opened
May 25 17:26:26 ppp: [wan_link0] LCP: auth: peer wants PAP, I want nothing
May 25 17:26:26 ppp: [wan_link0] PAP: using authname "chpalmer"
May 25 17:26:26 ppp: [wan_link0] PAP: sending REQUEST #1 len: 21
May 25 17:26:26 ppp: [wan_link0] LCP: LayerUp
May 25 17:26:26 ppp: [wan_link0] PAP: rec'd ACK #1 len: 5
May 25 17:26:26 ppp: [wan_link0] LCP: authorization successful
May 25 17:26:26 ppp: [wan_link0] Link: Join bundle "wan"
May 25 17:26:26 ppp: [wan] Bundle: Status update: up 2 links, total bandwidth 128000 bps

http://forum.pfsense.org/index.php/topic,34360.0.html

Epoch

You should probably set your MTU to 1486 and your MRU to 1492. That would solve your MTU issue, MLPPP adds an extra 6 bytes of overhead, so instead of 1492 you should have 1486 for MTU on each link. MRU is probably correctly negotiated with your provider at 1492.

clarknova

Here's mine, FWIW. No fancy settings, it's always just worked for me. My provider uses Juniper.

clarknova_mpd_wan.conf.txt

Epoch

I talked to my provider, what I am seeing is an issue between mpd and the LNS. The access concentrator is rejecting multilink as per their config, but their LNS is set to always renegotiate LCP paramaters. Mpd isn't renegotiating the LCP parameters with their LNS gear despite their LNS gear announcing capabilities once I actually reach it.

I will load the latest i386 snapshot on the box today and retry, though I expect that I will still see the same issues.

Epoch

I have just reloaded to the following snapshop via a fresh install:
2.0-RC2 (i386)
built on Thu May 26 08:49:46 EDT 2011

I still can't MLPPP working, I have verified configs on the Cisco hardware with my ISP, and confirmed that the issue is in fact pfSense/mpd and its complete and utter reluctance to renegotiate link parameters via LCP. Once they are set, they are set, and it refuses to do anything else. Screenshots below, along with the relevant section from the ppp logs showing the renegotiation faliure. Their Cisco gear announces MLPPP after I log in with a MLPPP enabled login to the LAC and get passed to the LNS, it tries to renegotiate with mpd to get MRRU and multilink running, but mpd just refuses to renegotiate.
The LNS is configued to always renegotiate LCP paramaters, and you can see in the logs that it is announcing and trying to renegotiate, but mpd just doesn't want to do the same.

ppp: [wan_link0] LCP: LayerStart
ppp: [wan_link0] Link: reconnection attempt 11 in 3 seconds
ppp: [wan_link0] Link: reconnection attempt 11
ppp: [wan_link0] PPPoE: Connecting to ''
ppp: PPPoE: rec'd ACNAME "ISP"
ppp: [wan_link0] PPPoE: connection successful
ppp: [wan_link0] Link: UP event
ppp: [wan_link0] LCP: Up event
ppp: [wan_link0] LCP: state change Starting --> Req-Sent
ppp: [wan_link0] LCP: SendConfigReq #45
ppp: [wan_link0]   PROTOCOMP
ppp: [wan_link0]   MRU 1492
ppp: [wan_link0]   MAGICNUM 414c2618
ppp: [wan_link0]   MP MRRU 1524
ppp: [wan_link0]   ENDPOINTDISC [802.1] MAC
ppp: [wan_link0] LCP: rec'd Configure Request #1 (Req-Sent)
ppp: [wan_link0]   MRU 1492
ppp: [wan_link0]   AUTHPROTO PAP
ppp: [wan_link0]   MAGICNUM a5384b70
ppp: [wan_link0] LCP: SendConfigAck #1
ppp: [wan_link0]   MRU 1492
ppp: [wan_link0]   AUTHPROTO PAP
ppp: [wan_link0]   MAGICNUM a5384b70
ppp: [wan_link0] LCP: state change Req-Sent --> Ack-Sent
ppp: [wan_link0] LCP: rec'd Configure Reject #45 (Ack-Sent)
ppp: [wan_link0]   MP MRRU 1524
ppp: [wan_link0] LCP: SendConfigReq #46
ppp: [wan_link0]   PROTOCOMP
ppp: [wan_link0]   MRU 1492
ppp: [wan_link0]   MAGICNUM 414c2618
ppp: [wan_link0] LCP: rec'd Configure Ack #46 (Ack-Sent)
ppp: [wan_link0]   PROTOCOMP
ppp: [wan_link0]   MRU 1492
ppp: [wan_link0]   MAGICNUM 414c2618
ppp: [wan_link0] LCP: state change Ack-Sent --> Opened
ppp: [wan_link0] LCP: auth: peer wants PAP, I want nothing
ppp: [wan_link0] PAP: using authname "username@isp"
ppp: [wan_link0] PAP: sending REQUEST #1 len: 36
ppp: [wan_link0] LCP: LayerUp
ppp: [wan_link0] LCP: rec'd Configure Request #1 (Opened)
ppp: [wan_link0]   MRU 1492
ppp: [wan_link0]   AUTHPROTO PAP
ppp: [wan_link0]   MAGICNUM a77bb05e
ppp: [wan_link0]   MP MRRU 1524
ppp: [wan_link0]   ENDPOINTDISC [LOCAL] MAC
ppp: [wan_link0] LCP: LayerDown
ppp: [wan_link0] LCP: SendConfigReq #47
ppp: [wan_link0]   PROTOCOMP
ppp: [wan_link0]   MRU 1492
ppp: [wan_link0]   MAGICNUM 414c2618
ppp: [wan_link0] LCP: SendConfigAck #1
ppp: [wan_link0]   MRU 1492
ppp: [wan_link0]   AUTHPROTO PAP
ppp: [wan_link0]   MAGICNUM a77bb05e
ppp: [wan_link0]   MP MRRU 1524
ppp: [wan_link0]   ENDPOINTDISC [LOCAL] MAC
ppp: [wan_link0] LCP: state change Opened --> Ack-Sent
ppp: [wan_link0] LCP: rec'd Configure Ack #47 (Ack-Sent)
ppp: [wan_link0]   PROTOCOMP
ppp: [wan_link0]   MRU 1492
ppp: [wan_link0]   MAGICNUM 414c2618
ppp: [wan_link0] LCP: state change Ack-Sent --> Opened
ppp: [wan_link0] LCP: auth: peer wants PAP, I want nothing
ppp: [wan_link0] PAP: using authname "user@isp"
ppp: [wan_link0] PAP: sending REQUEST #1 len: 36
ppp: [wan_link0] LCP: LayerUp
ppp: [wan_link0] PAP: rec'd ACK #1 len: 5
ppp: [wan_link0] LCP: authorization successful
ppp: [wan_link0] Can't join bundle wan without multilink negotiated.
ppp: [wan_link0] link did not validate in bundle
ppp: [wan_link0] LCP: parameter negotiation failed
ppp: [wan_link0] LCP: state change Opened --> Stopping
ppp: [wan_link0] LCP: SendTerminateReq #48
ppp: [wan_link0] LCP: LayerDown

ppp1.jpg_thumb

ppp2.jpg_thumb

eri--

You need to enable more debugging to really understand what is not going well there.

Check the log statement here http://mpd.sourceforge.net/doc5/mpd18.html#18

Epoch

I set up the PPP settings again, turned on NOSHORTSEQ, and added a bunch of debugging to my config, saved it in /conf/mpd_wan.conf The end result is that there is no real change.

Logs below, as well as a copy of my config file. I can't think of anything else to log, and from all appearances, and from verification from the other side, my pfSense box never renegotiates LCP parameters and therefore won't negotiate multilink.

ppp: Multi-link PPP daemon for FreeBSD
ppp:  
ppp: process 9975 started, version 5.5 (root@FreeBSD_8.0_pfSense_2.0-snaps.pfsense.org 13:37 25-May-2011)
ppp: web: web is not running
ppp: [wan] Bundle: Interface ng0 created
ppp: [wan_link0] Link: OPEN event
ppp: [wan_link0] LCP: Open event
ppp: [wan_link0] LCP: state change Initial --> Starting
ppp: [wan_link0] LCP: LayerStart
ppp: [wan_link1] Link: OPEN event
ppp: [wan_link1] LCP: Open event
ppp: [wan_link1] LCP: state change Initial --> Starting
ppp: [wan_link1] LCP: LayerStart
ppp: [wan_link0] PPPoE: Connecting to '*'
ppp: [wan_link1] PPPoE: Connecting to '*'
ppp: PPPoE: rec'd ACNAME ""
ppp: PPPoE: rec'd ACNAME ""
ppp: [wan_link0] PPPoE: connection successful
ppp: [wan_link0] Link: UP event
ppp: [wan_link0] LCP: Up event
ppp: [wan_link0] LCP: state change Starting --> Req-Sent
ppp: [wan_link0] LCP: SendConfigReq #1
ppp: [wan_link0]   PROTOCOMP
ppp: [wan_link0]   MRU 1492
ppp: [wan_link0]   MAGICNUM 550c7b47
ppp: [wan_link0]   MP MRRU 1524
ppp: [wan_link0]   MP SHORTSEQ
ppp: [wan_link0]   ENDPOINTDISC [802.1] 00 30 48 db 09 36
ppp: [wan_link1] PPPoE: connection successful
ppp: [wan_link1] Link: UP event
ppp: [wan_link1] LCP: Up event
ppp: [wan_link1] LCP: state change Starting --> Req-Sent
ppp: [wan_link1] LCP: SendConfigReq #1
ppp: [wan_link1]   PROTOCOMP
ppp: [wan_link1]   MRU 1492
ppp: [wan_link1]   MAGICNUM 60817fd1
ppp: [wan_link1]   MP MRRU 1524
ppp: [wan_link1]   MP SHORTSEQ
ppp: [wan_link1]   ENDPOINTDISC [802.1] 00 30 48 db 09 36
ppp: [wan_link0] LCP: rec'd Configure Request #1 (Req-Sent)
ppp: [wan_link0]   MRU 1492
ppp: [wan_link0]   AUTHPROTO PAP
ppp: [wan_link0]   MAGICNUM aa660d1b
ppp: [wan_link0] LCP: SendConfigAck #1
ppp: [wan_link0]   MRU 1492
ppp: [wan_link0]   AUTHPROTO PAP
ppp: [wan_link0]   MAGICNUM aa660d1b
ppp: [wan_link0] LCP: state change Req-Sent --> Ack-Sent
ppp: [wan_link0] LCP: rec'd Configure Reject #1 (Ack-Sent)
ppp: [wan_link0]   MP MRRU 1524
ppp: [wan_link0]   MP SHORTSEQ
ppp: [wan_link0] LCP: SendConfigReq #2
ppp: [wan_link0]   PROTOCOMP
ppp: [wan_link0]   MRU 1492
ppp: [wan_link0]   MAGICNUM 550c7b47
ppp: [wan_link1] LCP: rec'd Configure Request #1 (Req-Sent)
ppp: [wan_link1]   MRU 1492
ppp: [wan_link1]   AUTHPROTO PAP
ppp: [wan_link1]   MAGICNUM aa660d28
ppp: [wan_link1] LCP: SendConfigAck #1
ppp: [wan_link1]   MRU 1492
ppp: [wan_link1]   AUTHPROTO PAP
ppp: [wan_link1]   MAGICNUM aa660d28
ppp: [wan_link1] LCP: state change Req-Sent --> Ack-Sent
ppp: [wan_link1] LCP: rec'd Configure Reject #1 (Ack-Sent)
ppp: [wan_link1]   MP MRRU 1524
ppp: [wan_link1]   MP SHORTSEQ
ppp: [wan_link1] LCP: SendConfigReq #2
ppp: [wan_link1]   PROTOCOMP
ppp: [wan_link1]   MRU 1492
ppp: [wan_link1]   MAGICNUM 60817fd1
ppp: [wan_link0] LCP: rec'd Configure Ack #2 (Ack-Sent)
ppp: [wan_link0]   PROTOCOMP
ppp: [wan_link0]   MRU 1492
ppp: [wan_link0]   MAGICNUM 550c7b47
ppp: [wan_link0] LCP: state change Ack-Sent --> Opened
ppp: [wan_link0] LCP: auth: peer wants PAP, I want nothing
ppp: [wan_link0] PAP: using authname "user@isp"
ppp: [wan_link0] PAP: sending REQUEST #1 len: 35
ppp: [wan_link0] LCP: LayerUp
ppp: [wan_link1] LCP: rec'd Configure Ack #2 (Ack-Sent)
ppp: [wan_link1]   PROTOCOMP
ppp: [wan_link1]   MRU 1492
ppp: [wan_link1]   MAGICNUM 60817fd1
ppp: [wan_link1] LCP: state change Ack-Sent --> Opened
ppp: [wan_link1] LCP: auth: peer wants PAP, I want nothing
ppp: [wan_link1] PAP: using authname "user@isp"
ppp: [wan_link1] PAP: sending REQUEST #1 len: 35
ppp: [wan_link1] LCP: LayerUp
ppp: [wan_link0] LCP: rec'd Configure Request #1 (Opened)
ppp: [wan_link0]   MRU 1492
ppp: [wan_link0]   AUTHPROTO PAP
ppp: [wan_link0]   MAGICNUM aca83802
ppp: [wan_link0]   MP MRRU 1524
ppp: [wan_link0]   ENDPOINTDISC [LOCAL] 6c 6e 73 34 2d 57 4e 44 53 4f 4e 31 37
ppp: [wan_link0] LCP: LayerDown
ppp: [wan_link0] LCP: SendConfigReq #3
ppp: [wan_link0]   PROTOCOMP
ppp: [wan_link0]   MRU 1492
ppp: [wan_link0]   MAGICNUM 550c7b47
ppp: [wan_link0] LCP: SendConfigAck #1
ppp: [wan_link0]   MRU 1492
ppp: [wan_link0]   AUTHPROTO PAP
ppp: [wan_link0]   MAGICNUM aca83802
ppp: [wan_link0]   MP MRRU 1524
ppp: [wan_link0]   ENDPOINTDISC [LOCAL] 6c 6e 73 34 2d 57 4e 44 53 4f 4e 31 37
ppp: [wan_link0] LCP: state change Opened --> Ack-Sent
ppp: [wan_link1] LCP: rec'd Configure Request #1 (Opened)
ppp: [wan_link1]   MRU 1492
ppp: [wan_link1]   AUTHPROTO PAP
ppp: [wan_link1]   MAGICNUM aca83820
ppp: [wan_link1]   MP MRRU 1524
ppp: [wan_link1]   ENDPOINTDISC [LOCAL] 6c 6e 73 34 2d 57 4e 44 53 4f 4e 31 37
ppp: [wan_link1] LCP: LayerDown
ppp: [wan_link1] LCP: SendConfigReq #3
ppp: [wan_link1]   PROTOCOMP
ppp: [wan_link1]   MRU 1492
ppp: [wan_link1]   MAGICNUM 60817fd1
ppp: [wan_link1] LCP: SendConfigAck #1
ppp: [wan_link1]   MRU 1492
ppp: [wan_link1]   AUTHPROTO PAP
ppp: [wan_link1]   MAGICNUM aca83820
ppp: [wan_link1]   MP MRRU 1524
ppp: [wan_link1]   ENDPOINTDISC [LOCAL] 6c 6e 73 34 2d 57 4e 44 53 4f 4e 31 37
ppp: [wan_link1] LCP: state change Opened --> Ack-Sent
ppp: [wan_link0] LCP: rec'd Configure Ack #3 (Ack-Sent)
ppp: [wan_link0]   PROTOCOMP
ppp: [wan_link0]   MRU 1492
ppp: [wan_link0]   MAGICNUM 550c7b47
ppp: [wan_link0] LCP: state change Ack-Sent --> Opened
ppp: [wan_link0] LCP: auth: peer wants PAP, I want nothing
ppp: [wan_link0] PAP: using authname "user@isp"
ppp: [wan_link0] PAP: sending REQUEST #1 len: 35
ppp: [wan_link0] LCP: LayerUp
ppp: [wan_link1] LCP: rec'd Configure Ack #3 (Ack-Sent)
ppp: [wan_link1]   PROTOCOMP
ppp: [wan_link1]   MRU 1492
ppp: [wan_link1]   MAGICNUM 60817fd1
ppp: [wan_link1] LCP: state change Ack-Sent --> Opened
ppp: [wan_link1] LCP: auth: peer wants PAP, I want nothing
ppp: [wan_link1] PAP: using authname "user@isp"
ppp: [wan_link1] PAP: sending REQUEST #1 len: 35
ppp: [wan_link1] LCP: LayerUp
ppp: [wan_link0] PAP: rec'd ACK #1 len: 5
ppp: [wan_link0] LCP: authorization successful
ppp: [wan_link0] Link: Matched action 'bundle "wan" ""'
ppp: [wan_link0] Link: Join bundle "wan"
ppp: [wan] Bundle: Status update: up 1 link, total bandwidth 64000 bps
ppp: [wan] IPCP: Open event
ppp: [wan] IPCP: state change Initial --> Starting
ppp: [wan] IPCP: LayerStart
ppp: [wan] IPCP: Up event
ppp: [wan] IPCP: state change Starting --> Req-Sent
ppp: [wan] IPCP: SendConfigReq #1
ppp: [wan]   IPADDR 0.0.0.0
ppp: [wan]   COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
ppp: [wan] IPCP: rec'd Configure Request #1 (Req-Sent)
ppp: [wan]   IPADDR #
ppp: [wan]     # is OK
ppp: [wan] IPCP: SendConfigAck #1
ppp: [wan]   IPADDR #
ppp: [wan] IPCP: state change Req-Sent --> Ack-Sent
ppp: [wan_link1] PAP: rec'd ACK #1 len: 5
ppp: [wan_link1] LCP: authorization successful
ppp: [wan_link1] Can't join bundle wan without multilink negotiated.
ppp: [wan_link1] link did not validate in bundle
ppp: [wan_link1] LCP: parameter negotiation failed
ppp: [wan_link1] LCP: state change Opened --> Stopping
ppp: [wan_link1] LCP: SendTerminateReq #4
ppp: [wan_link1] LCP: LayerDown

What I am reading from those logs is the following:

I bring up a PPPoE session, I announce multilink via the MRRU parameter.
The ISP access concentrator rejects multilink by rejecting MRRU.
The ISP also rejects NOSHORTSEQ.
I renegotiate without multilink (MRRU no longer negotiated).
I connect, I authorize with the RADIUS server.
I get passed to the access server, which announces multilink via the MRRU parameter.
The access server attempts to renegotiate LCP parameters.
I ignore that request and restate my LCP parameters that I established with the access server.
The access server acknowledges LCP parameters that it tried to set (since they are required to establish my multilink session)
I move ahead and try to join the WAN bundle.
The first to join the WAN bundle succeeds, without negotiating multilink.
The second link tries to join the WAN bundle but fails because both it and the first link failed to negotiate multilink.

pfSense/mpd chronically refuses to renegotiate LCP parameters once they are accepted by the first gear it comes across. I don't know why, but that is what appears to be happening.

If you can think of something in my logs that wasn't there that should be I will be happy to retry this, but I don't see logging options for mpd that would help.

mpd_wan.txt

Epoch

Found more things to log, I will give that a try later and see if anything else shows up in the logs. I apologize for being a little slow, I should have seen the asterisk on those manual pages and figured out that there were additional debugging logs to turn on for LCP logging.
More results later, hopefully with relevant details.

Epoch

I enabled logging for BUND, BUND2, AUTH, AUTH2, LCP, LCP2, CCP, CCP2, ECP, ECP2, ECHO, and the other defaults and came up with the following in my logs. It really does look like mpd5 is getting the configuration request sent by my ISP's LNS and completely ignoring it.

ppp: Multi-link PPP daemon for FreeBSD
ppp:  
ppp: process 8179 started, version 5.5 (root@FreeBSD_8.0_pfSense_2.0-snaps.pfsense.org 13:37 25-May-2011)
ppp: web: web is not running
ppp: [wan] Bundle: Interface ng0 created
ppp: [wan_link0] Link: OPEN event
ppp: [wan_link0] LCP: Open event
ppp: [wan_link0] LCP: state change Initial --> Starting
ppp: [wan_link0] LCP: LayerStart
ppp: [wan_link1] Link: OPEN event
ppp: [wan_link1] LCP: Open event
ppp: [wan_link1] LCP: state change Initial --> Starting
ppp: [wan_link1] LCP: LayerStart
ppp: [wan_link0] PPPoE: Connecting to ''
ppp: [wan_link1] PPPoE: Connecting to ''
ppp: PPPoE: rec'd ACNAME "lns3-WNDSON17"
ppp: PPPoE: rec'd ACNAME "lns3-WNDSON17"
ppp: [wan_link1] PPPoE: connection successful
ppp: [wan_link1] Link: UP event
ppp: [wan_link1] LCP: Up event
ppp: [wan_link1] LCP: state change Starting --> Req-Sent
ppp: [wan_link1] LCP: phase shift DEAD --> ESTABLISH
ppp: [wan_link1] LCP: SendConfigReq #1
ppp: [wan_link1]   PROTOCOMP
ppp: [wan_link1]   MRU 1492
ppp: [wan_link1]   MAGICNUM 27336dd6
ppp: [wan_link1]   MP MRRU 1524
ppp: [wan_link1]   MP SHORTSEQ
ppp: [wan_link1]   ENDPOINTDISC [802.1] 00 30 48 db 09 36
ppp: [wan_link0] PPPoE: connection successful
ppp: [wan_link0] Link: UP event
ppp: [wan_link0] LCP: Up event
ppp: [wan_link0] LCP: state change Starting --> Req-Sent
ppp: [wan_link0] LCP: phase shift DEAD --> ESTABLISH
ppp: [wan_link0] LCP: SendConfigReq #1
ppp: [wan_link0]   PROTOCOMP
ppp: [wan_link0]   MRU 1492
ppp: [wan_link0]   MAGICNUM 2458176a
ppp: [wan_link0]   MP MRRU 1524
ppp: [wan_link0]   MP SHORTSEQ
ppp: [wan_link0]   ENDPOINTDISC [802.1] 00 30 48 db 09 36
ppp: [wan_link1] LCP: rec'd Configure Request #1 (Req-Sent)
ppp: [wan_link1]   MRU 1492
ppp: [wan_link1]   AUTHPROTO PAP
ppp: [wan_link1]   MAGICNUM be84fab0
ppp: [wan_link1] LCP: SendConfigAck #1
ppp: [wan_link1]   MRU 1492
ppp: [wan_link1]   AUTHPROTO PAP
ppp: [wan_link1]   MAGICNUM be84fab0
ppp: [wan_link1] LCP: state change Req-Sent --> Ack-Sent
ppp: [wan_link1] LCP: rec'd Configure Reject #1 (Ack-Sent)
ppp: [wan_link1]   MP MRRU 1524
ppp: [wan_link1]   MP SHORTSEQ
ppp: [wan_link1] LCP: SendConfigReq #2
ppp: [wan_link1]   PROTOCOMP
ppp: [wan_link1]   MRU 1492
ppp: [wan_link1]   MAGICNUM 27336dd6
ppp: [wan_link0] LCP: rec'd Configure Request #1 (Req-Sent)
ppp: [wan_link0]   MRU 1492
ppp: [wan_link0]   AUTHPROTO PAP
ppp: [wan_link0]   MAGICNUM be84fabd
ppp: [wan_link0] LCP: SendConfigAck #1
ppp: [wan_link0]   MRU 1492
ppp: [wan_link0]   AUTHPROTO PAP
ppp: [wan_link0]   MAGICNUM be84fabd
ppp: [wan_link0] LCP: state change Req-Sent --> Ack-Sent
ppp: [wan_link0] LCP: rec'd Configure Reject #1 (Ack-Sent)
ppp: [wan_link0]   MP MRRU 1524
ppp: [wan_link0]   MP SHORTSEQ
ppp: [wan_link0] LCP: SendConfigReq #2
ppp: [wan_link0]   PROTOCOMP
ppp: [wan_link0]   MRU 1492
ppp: [wan_link0]   MAGICNUM 2458176a
ppp: [wan_link1] LCP: rec'd Configure Ack #2 (Ack-Sent)
ppp: [wan_link1]   PROTOCOMP
ppp: [wan_link1]   MRU 1492
ppp: [wan_link1]   MAGICNUM 27336dd6
ppp: [wan_link1] LCP: state change Ack-Sent --> Opened
ppp: [wan_link1] LCP: phase shift ESTABLISH --> AUTHENTICATE
ppp: [wan_link1] LCP: auth: peer wants PAP, I want nothing
ppp: [wan_link1] PAP: using authname "mppp%user@mnsi.net"
ppp: [wan_link1] PAP: sending REQUEST #1 len: 36
ppp: [wan_link1] LCP: LayerUp
ppp: [wan_link0] LCP: rec'd Configure Ack #2 (Ack-Sent)
ppp: [wan_link0]   PROTOCOMP
ppp: [wan_link0]   MRU 1492
ppp: [wan_link0]   MAGICNUM 2458176a
ppp: [wan_link0] LCP: state change Ack-Sent --> Opened
ppp: [wan_link0] LCP: phase shift ESTABLISH --> AUTHENTICATE
ppp: [wan_link0] LCP: auth: peer wants PAP, I want nothing
ppp: [wan_link0] PAP: using authname "mppp%user@mnsi.net"
ppp: [wan_link0] PAP: sending REQUEST #1 len: 36
ppp: [wan_link0] LCP: LayerUp
ppp: [wan_link1] LCP: rec'd Configure Request #1 (Opened)
ppp: [wan_link1]   MRU 1492
ppp: [wan_link1]   AUTHPROTO PAP
ppp: [wan_link1]   MAGICNUM c0c2405b
ppp: [wan_link1]   MP MRRU 1524
ppp: [wan_link1]   ENDPOINTDISC [LOCAL] 6c 6e 73 34 2d 57 4e 44 53 4f 4e 31 37
ppp: [wan_link1] LCP: LayerDown
ppp: [wan_link1] LCP: SendConfigReq #3
ppp: [wan_link1]   PROTOCOMP
ppp: [wan_link1]   MRU 1492
ppp: [wan_link1]   MAGICNUM 27336dd6
ppp: [wan_link1] LCP: SendConfigAck #1
ppp: [wan_link1]   MRU 1492
ppp: [wan_link1]   AUTHPROTO PAP
ppp: [wan_link1]   MAGICNUM c0c2405b
ppp: [wan_link1]   MP MRRU 1524
ppp: [wan_link1]   ENDPOINTDISC [LOCAL] 6c 6e 73 34 2d 57 4e 44 53 4f 4e 31 37
ppp: [wan_link1] LCP: state change Opened --> Ack-Sent
ppp: [wan_link1] LCP: phase shift AUTHENTICATE --> ESTABLISH
ppp: [wan_link1] AUTH: Cleanup
ppp: [wan_link0] LCP: rec'd Configure Request #1 (Opened)
ppp: [wan_link0]   MRU 1492
ppp: [wan_link0]   AUTHPROTO PAP
ppp: [wan_link0]   MAGICNUM c0c24075
ppp: [wan_link0]   MP MRRU 1524
ppp: [wan_link0]   ENDPOINTDISC [LOCAL] 6c 6e 73 34 2d 57 4e 44 53 4f 4e 31 37
ppp: [wan_link0] LCP: LayerDown
ppp: [wan_link0] LCP: SendConfigReq #3
ppp: [wan_link0]   PROTOCOMP
ppp: [wan_link0]   MRU 1492
ppp: [wan_link0]   MAGICNUM 2458176a
ppp: [wan_link0] LCP: SendConfigAck #1
ppp: [wan_link0]   MRU 1492
ppp: [wan_link0]   AUTHPROTO PAP
ppp: [wan_link0]   MAGICNUM c0c24075
ppp: [wan_link0]   MP MRRU 1524
ppp: [wan_link0]   ENDPOINTDISC [LOCAL] 6c 6e 73 34 2d 57 4e 44 53 4f 4e 31 37
ppp: [wan_link0] LCP: state change Opened --> Ack-Sent
ppp: [wan_link0] LCP: phase shift AUTHENTICATE --> ESTABLISH
ppp: [wan_link0] AUTH: Cleanup
ppp: [wan_link1] LCP: rec'd Configure Ack #3 (Ack-Sent)
ppp: [wan_link1]   PROTOCOMP
ppp: [wan_link1]   MRU 1492
ppp: [wan_link1]   MAGICNUM 27336dd6
ppp: [wan_link1] LCP: state change Ack-Sent --> Opened
ppp: [wan_link1] LCP: phase shift ESTABLISH --> AUTHENTICATE
ppp: [wan_link1] LCP: auth: peer wants PAP, I want nothing
ppp: [wan_link1] PAP: using authname "mppp%user@mnsi.net"
ppp: [wan_link1] PAP: sending REQUEST #1 len: 36
ppp: [wan_link1] LCP: LayerUp
ppp: [wan_link0] LCP: rec'd Configure Ack #3 (Ack-Sent)
ppp: [wan_link0]   PROTOCOMP
ppp: [wan_link0]   MRU 1492
ppp: [wan_link0]   MAGICNUM 2458176a
ppp: [wan_link0] LCP: state change Ack-Sent --> Opened
ppp: [wan_link0] LCP: phase shift ESTABLISH --> AUTHENTICATE
ppp: [wan_link0] LCP: auth: peer wants PAP, I want nothing
ppp: [wan_link0] PAP: using authname "mppp%user@mnsi.net"
ppp: [wan_link0] PAP: sending REQUEST #1 len: 36
ppp: [wan_link0] LCP: LayerUp
ppp: [wan_link1] PAP: rec'd ACK #1 len: 5
ppp: [wan_link1] LCP: authorization successful
ppp: [wan_link1] LCP: phase shift AUTHENTICATE --> NETWORK
ppp: [wan_link1] Link: Matched action 'bundle "wan" ""'
ppp: [wan_link1] Link: Join bundle "wan"
ppp: [wan] Bundle: Status update: up 1 link, total bandwidth 64000 bps
ppp: [wan] IPCP: Open event
ppp: [wan] IPCP: state change Initial --> Starting
ppp: [wan] IPCP: LayerStart
ppp: [wan] IPCP: Up event
ppp: [wan] IPCP: state change Starting --> Req-Sent
ppp: [wan] IPCP: SendConfigReq #1
ppp: [wan]   IPADDR 0.0.0.0
ppp: [wan]   COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
ppp: [wan] IPCP: rec'd Configure Request #1 (Req-Sent)
ppp: [wan]   IPADDR 216.8.136.171
ppp: [wan]     216.8.136.171 is OK
ppp: [wan] IPCP: SendConfigAck #1
ppp: [wan]   IPADDR 216.8.136.171
ppp: [wan] IPCP: state change Req-Sent --> Ack-Sent
ppp: [wan_link0] PAP: rec'd ACK #1 len: 5
ppp: [wan_link0] LCP: authorization successful
ppp: [wan_link0] LCP: phase shift AUTHENTICATE --> NETWORK
ppp: [wan_link0] Can't join bundle wan without multilink negotiated.
ppp: [wan_link0] link did not validate in bundle
ppp: [wan_link0] LCP: parameter negotiation failed
ppp: [wan_link0] LCP: state change Opened --> Stopping
ppp: [wan_link0] LCP: phase shift NETWORK --> TERMINATE
ppp: [wan_link0] AUTH: Cleanup
ppp: [wan_link0] LCP: SendTerminateReq #4
ppp: [wan_link0] LCP: LayerDown
ppp: [wan_link0] rec'd proto IPCP during terminate phase
ppp: [wan] IPCP: rec'd Configure Reject #1 (Ack-Sent)
ppp: [wan]   COMPPROTO VJCOMP, 16 comp. channels, no comp-cid
ppp: [wan] IPCP: SendConfigReq #2
ppp: [wan]   IPADDR 0.0.0.0
ppp: [wan_link0] LCP: rec'd Terminate Ack #4 (Stopping)
ppp: [wan_link0] LCP: state change Stopping --> Stopped
ppp: [wan_link0] LCP: phase shift TERMINATE --> ESTABLISH
ppp: [wan_link0] LCP: LayerFinish
ppp: [wan_link0] PPPoE: connection closed
ppp: [wan_link0] Link: DOWN event
ppp: [wan_link0] LCP: Close event
ppp: [wan_link0] LCP: state change Stopped --> Closed
ppp: [wan_link0] LCP: Down event
ppp: [wan_link0] LCP: state change Closed --> Initial
ppp: [wan_link0] LCP: phase shift ESTABLISH --> DEAD
ppp: [wan] IPCP: rec'd Configure Nak #2 (Ack-Sent)
ppp: [wan]   IPADDR MYIP
ppp: [wan]     MYIP is OK
ppp: [wan] IPCP: SendConfigReq #3
ppp: [wan]   IPADDR MYIP
ppp: [wan] IPCP: rec'd Configure Ack #3 (Ack-Sent)
ppp: [wan]   IPADDR MYIP
ppp: [wan] IPCP: state change Ack-Sent --> Opened
ppp: [wan] IPCP: LayerUp
ppp: [wan]   MYIP -> GATEWAY
ppp: [wan] IFACE: Up event

I may be incorrect, but what I see is the following:

1. PPPoE session opens
2. mpd5 sends a config request to the access concentrator with the settings from mpd_wan.conf
3. ISP's access concentrator gets the config, negotiates a new MAGICNUM, and rejects MRRU and SHORTSEQ.
4. mpd5 renegotiates with the access concentrator without MRRU, without SHORTSEQ, and with the new MAGICNUM
5. mpd5 authenticates with my ISP using my username and password
6. mpd5 gets passed from the access concentrator to the access server.
7. ISP's access server sends a configuration request which has a new MAGICNUM, MRRU settings for MLPPP.
8. mpd5 resends the LCP parameters it negotiated with the access concentrator instead of negotiating the settings that the access server wants.
9. PPPoE session is established without multilink, and without the correct MAGICNUM that the access server requested.
10. mpd5 cannot join two links to the WAN bundle because it never negotiates multilink with the ISP.

The root cause is that mpd doesn't appear to respond correctly to the LCP renegotiation from the LNS. The LNS is doing the exact same thing to mpd that mpd attempted with the access concentrator, but mpd isn't behaving in a way that lets the LNS renegotiate LCP.

chpalmer

Saw your post yesterday over at the MPD site… Kinda wish I knew Russian over there... Thanks for the updates!

chpalmer

I find this interesting from the manual…

4.16. Web server

Mpd provides HTTP interface for monitoring and control purposes. This chapter describes commands for configuring Mpd's web server.

set web open

Opens the web server, i.e., creates the listening TCP socket.
set web close

Closes the web server, i.e., closes the listening TCP socket.
set web self ip [ port ]

Sets the credentials for the web-listener. After changing one of these options, the web must be closed and re-opened for the changes to take effect.

The default is '127.0.0.1 5006'.

set web enable option …
set web disable option ...

These commands configure various web server options.

The enable and disable commands determine whether we want the corresponding option.

The options available for the web are:
auth

This option enables basic authorisation on web server.

The default is enable.

You can send any set of command allowed by privileges via WEB server for mpd infrastructure integration. Depending on URL used mpd supports two response formats: text/html (/cmd?command1&...) and text/plain (/bincmd?command1&...).

Epoch

I saw that Mpd supports a bunch of cool options, but I have yet to find one that would help.
Basically, what I am seeing appears to be something that was fixed in 2008 in the mpd5 cvs, but maybe it didn't make its way into mpd5.5 in pfsense.

This is where I see the same issue diagnosed by one of the authors of mpd, and that he put a patch in to resolve this very issue.

Same issue, identified by Alexander Motin

Patched by Alexander Motin

That is what I don't understand, this issue appears to have been fixed over 3 years ago, but somehow I have this very problem. Maybe there is a recursion, I don't really know, but in theory it should impact Teksavvy users.

In theory, if a Teksavvy user restarted a mlppp session they should see in their logs similar things to what I have in mine, but it should renegotiate after the access concentrator. For some reason, mine won't. It probably wouldn't hurt to see those logs though and see if something is different since Teksavvy uses Juniper gear instead of Cisco gear.

clarknova

@Epoch:

It probably wouldn't hurt to see those logs though and see if something is different since Teksavvy uses Juniper gear instead of Cisco gear.

Enjoy.

ppp.log.txt

Epoch

There is one key difference in between your logs and mine:
"May 11 23:30:13 pfsense ppp: [wan_link0] LCP: rec'd Configure Nak #3 (Ack-Sent)"

When you hit the access server you get a CONFNAK or "Configure Negative Acknowledgement" message which renegotiates MRRU, it looks like I am not getting a CONFNAK message from my ISP and their gear.

clarknova

You may want to ask gnhb to look at this thread. I believe he did the bulk of the work getting mlppp into pfsense, so he may have some insight for you on this problem.