Multi-PPPoE problem?

mgaudette

Hi,

I have a NanoBSD system with two PPPoE links. Those are unreliably working. What I've noticed is that only one comes up at any time, while the other either stays inactive, or doesn't get an IP address, or doesn't get a Gateway address.

Is there any known flaws with Multi-PPPoE setups? Is there any version known to be working with such a setup?

I have tried an april version and the May 26th version.

jimp

I haven't tried it (only have one PPPoE line) but I have used it as an OPT WAN and had it work.

Can you post all of the MPD logs from when both are connecting? They should be in the main system log.

mgaudette

I'll be glad to, but I am not sure what you are looking for. What exactly should I be sending you, and would that be found in system logs?

On another note, I get the following info from the PPPoE provider: (IPs changed, but the essence remains)

(taken from the Status-Interface page) - For the one PPPoE interface that is up.
IP: 72.27.32.204
Subnet mask 255.255.255.255 (that wasnt changed)
Gateway 66.236.201.11

Does it make any sense? The gateway lies way outside the subnet mask, and I did get some errors when trying to put that gateway in manually, but it's still there.

mgaudette

Some snapshot of the log, seems relevant (again, ip and PPoE username obfuscated):

Jun 4 11:50:04 opt1: [opt1L1] LCP: state change Closed –> Initial
Jun 4 11:50:04 opt1: [opt1L1] LCP: Down event
Jun 4 11:50:04 opt1: [opt1L1] Link: DOWN event
Jun 4 11:50:04 opt1: [opt1L1] LCP: LayerFinish
Jun 4 11:50:04 opt1: [opt1L1] LCP: state change Closing –> Closed
Jun 4 11:50:04 opt1: [opt1L1] LCP: rec'd Terminate Ack #69 (Closing)
Jun 4 11:50:04 opt1: [opt1L1] LCP: LayerDown
Jun 4 11:50:04 opt1: [opt1L1] LCP: SendTerminateReq #69
Jun 4 11:50:04 opt1: [opt1] IPCP: state change Closed –> Initial
Jun 4 11:50:04 opt1: [opt1] IPCP: Down event
Jun 4 11:50:04 opt1: [opt1] IPCP: state change Stopped –> Closed
Jun 4 11:50:04 opt1: [opt1] IPCP: Close event
Jun 4 11:50:04 opt1: [opt1] Bundle: Status update: up 0 links, total bandwidth 9600 bps
Jun 4 11:50:04 opt1: [opt1L1] Link: Leave bundle "opt1"
Jun 4 11:50:04 opt1: [opt1L1] LCP: state change Opened –> Closing
Jun 4 11:50:04 opt1: [opt1L1] LCP: Close event
Jun 4 11:50:04 opt1: [opt1L1] Link: CLOSE event
Jun 4 11:50:04 opt1: [opt1] Bundle: closing link "opt1L1"…
Jun 4 11:50:04 opt1: [opt1] Bundle: No NCPs left. Closing links…
Jun 4 11:50:04 opt1: [opt1] IPCP: LayerFinish
Jun 4 11:50:04 opt1: [opt1] IPCP: state change Stopping –> Stopped
Jun 4 11:50:04 opt1: [opt1] IPCP: rec'd Terminate Ack #3 (Stopping)
Jun 4 11:50:04 opt1: [opt1] IPCP: LayerDown
Jun 4 11:50:04 opt1: [opt1] IPCP: SendTerminateReq #3
Jun 4 11:50:04 opt1: [opt1] IPCP: state change Opened –> Stopping
Jun 4 11:50:04 opt1: [opt1] IPCP: parameter negotiation failed
Jun 4 11:50:04 opt1: [opt1] IFACE: IfaceChangeAddr() error, closing IPCP
Jun 4 11:50:04 opt1: [opt1] 70.21.56.12 -> 67.23.12.5
Jun 4 11:50:04 opt1: [opt1] IPCP: LayerUp
Jun 4 11:50:04 opt1: [opt1] IPCP: state change Ack-Rcvd –> Opened
Jun 4 11:50:04 opt1: [opt1] IPADDR 67.23.12.5
Jun 4 11:50:04 opt1: [opt1] IPCP: SendConfigAck #184
Jun 4 11:50:04 opt1: [opt1] 67.23.12.5 is OK
Jun 4 11:50:04 opt1: [opt1] IPADDR 67.23.12.5
Jun 4 11:50:04 opt1: [opt1] IPCP: rec'd Configure Request #184 (Ack-Rcvd)
Jun 4 11:50:03 opt1: [opt1] IPCP: state change Req-Sent –> Ack-Rcvd
Jun 4 11:50:03 opt1: [opt1] SECDNS 207.164.234.193
Jun 4 11:50:03 opt1: [opt1] PRIDNS 207.164.234.129
Jun 4 11:50:03 opt1: [opt1] IPADDR 70.21.56.12
Jun 4 11:50:03 opt1: [opt1] IPCP: rec'd Configure Ack #2 (Req-Sent)
Jun 4 11:50:03 opt1: [opt1] SECDNS 207.164.234.193
Jun 4 11:50:03 opt1: [opt1] PRIDNS 207.164.234.129
Jun 4 11:50:03 opt1: [opt1] IPADDR 70.21.56.12
Jun 4 11:50:03 opt1: [opt1] IPCP: SendConfigReq #2
Jun 4 11:50:03 opt1: [opt1] SECDNS 207.164.234.193
Jun 4 11:50:03 opt1: [opt1] PRIDNS 207.164.234.129
Jun 4 11:50:03 opt1: [opt1] 70.21.56.12 is OK
Jun 4 11:50:03 opt1: [opt1] IPADDR 70.21.56.12
Jun 4 11:50:03 opt1: [opt1] IPCP: rec'd Configure Nak #1 (Req-Sent)
Jun 4 11:50:03 opt1: [opt1] SECDNS 0.0.0.0
Jun 4 11:50:03 opt1: [opt1] PRIDNS 0.0.0.0
Jun 4 11:50:03 opt1: [opt1] IPADDR 0.0.0.0
Jun 4 11:50:03 opt1: [opt1] IPCP: SendConfigReq #1
Jun 4 11:50:03 opt1: [opt1] IPCP: state change Starting –> Req-Sent
Jun 4 11:50:03 opt1: [opt1] IPCP: Up event
Jun 4 11:50:03 opt1: [opt1] IPCP: LayerStart
Jun 4 11:50:03 opt1: [opt1] IPCP: state change Initial –> Starting
Jun 4 11:50:03 opt1: [opt1] IPCP: Open event
Jun 4 11:50:03 opt1: [opt1] Bundle: Status update: up 1 link, total bandwidth 64000 bps
Jun 4 11:50:03 opt1: [opt1L1] Link: Join bundle "opt1"
Jun 4 11:50:03 opt1: [opt1L1] Link: Matched action 'bundle "opt1" ""'
Jun 4 11:50:03 opt1: [opt1L1] LCP: authorization successful
Jun 4 11:50:03 opt1: [opt1L1] PAP: rec'd ACK #2 len: 5
Jun 4 11:50:03 opt1: [opt1L1] PAP: sending REQUEST #2 len: 33
Jun 4 11:50:03 opt1: [opt1L1] PAP: using authname "hiddenusername@bellnet.ca"
Jun 4 11:50:01 opt1: [opt1L1] LCP: LayerUp
Jun 4 11:50:01 opt1: [opt1L1] PAP: sending REQUEST #1 len: 33
Jun 4 11:50:01 opt1: [opt1L1] PAP: using authname "hiddenusername@bellnet.ca"
Jun 4 11:50:01 opt1: [opt1L1] LCP: auth: peer wants PAP, I want nothing
Jun 4 11:50:01 opt1: [opt1L1] LCP: state change Ack-Sent –> Opened
Jun 4 11:50:01 opt1: [opt1L1] MAGICNUM 79ba9924
Jun 4 11:50:01 opt1: [opt1L1] MRU 1492
Jun 4 11:50:01 opt1: [opt1L1] LCP: rec'd Configure Ack #68 (Ack-Sent)
Jun 4 11:50:01 opt1: [opt1L1] LCP: state change Req-Sent –> Ack-Sent
Jun 4 11:50:01 opt1: [opt1L1] MAGICNUM 47217eb3
Jun 4 11:50:01 opt1: [opt1L1] AUTHPROTO PAP
Jun 4 11:50:01 opt1: [opt1L1] MRU 1492
Jun 4 11:50:01 opt1: [opt1L1] LCP: SendConfigAck #221
Jun 4 11:50:01 opt1: [opt1L1] MAGICNUM 47217eb3
Jun 4 11:50:01 opt1: [opt1L1] AUTHPROTO PAP
Jun 4 11:50:01 opt1: [opt1L1] MRU 1492
Jun 4 11:50:01 opt1: [opt1L1] LCP: rec'd Configure Request #221 (Req-Sent)
Jun 4 11:50:01 opt1: [opt1L1] MAGICNUM 79ba9924
Jun 4 11:50:01 opt1: [opt1L1] MRU 1492
Jun 4 11:50:01 opt1: [opt1L1] LCP: SendConfigReq #68
Jun 4 11:50:01 opt1: [opt1L1] LCP: state change Starting –> Req-Sent
Jun 4 11:50:01 opt1: [opt1L1] LCP: Up event
Jun 4 11:50:01 opt1: [opt1L1] Link: UP event
Jun 4 11:50:01 opt1: [opt1L1] PPPoE: connection successful
Jun 4 11:50:01 opt1: PPPoE: rec'd ACNAME "bas5453-montrealak"
Jun 4 11:50:00 opt1: [opt1L1] PPPoE: Connecting to ''
Jun 4 11:50:00 opt1: [opt1L1] Link: reconnection attempt 21
Jun 4 11:49:57 opt1: [opt1L1] Link: reconnection attempt 21 in 3 seconds

jimp

That's normal with PPPoE, you can have a gateway outside of the subnet. For example my (working) PPPoE WAN looks like this:

IP address 72.x.x.192
Subnet mask 255.255.255.255
Gateway 10.34.29.1

Someone who knows MPD internals better will have to check those log entries out and see if that "IfaceChangeAddr() error" in the logs indicates anything bad.

mgaudette

On on June 4th version.

Actually I realized yesterday that I was having more than just Multi-PPPoE issues. Here is what I saw on even a single PPPoE:

The PPPoE connection timeout (9 seconds might) have been too low, because it did takes many many times for it to actually work (~20?), while on a Tomato based linksys routeur it worked reliably (but it took man seconds to come up, maybe 30 althought I have no logs to know what actually happened during those 30 secs.)
Both links, it turns out, have the same gateway. Would that prevent both from working at the same time?

jimp

Not sure about 1), but 2) would definitely be a problem.

clarknova

Have you ruled out mlppp as an option? Your provider would have to support it.

mgaudette

@jimp:

Not sure about 1), but 2) would definitely be a problem.

Thanks. I figured about 2), but I am hopeful to get at least one PPPoE connection working. What can I do to help troubleshoot this?