Skip site navigation (1)Skip section navigation (2)
Date:      Tue, 7 Dec 2004 21:06:55 GMT
From:      Mike Tancsa <mike@sentex.net>
To:        freebsd-gnats-submit@FreeBSD.org
Subject:   bin/74821: PPPoE with LQR is broken for users connecting to a Juniper ERX
Message-ID:  <200412072106.iB7L6tZr039841@www.freebsd.org>
Resent-Message-ID: <200412072110.iB7LANE7007956@freefall.freebsd.org>

next in thread | raw e-mail | index | archive | help

>Number:         74821
>Category:       bin
>Synopsis:       PPPoE with LQR is broken for users connecting to a Juniper ERX
>Confidential:   no
>Severity:       non-critical
>Priority:       medium
>Responsible:    freebsd-bugs
>State:          open
>Quarter:        
>Keywords:       
>Date-Required:
>Class:          sw-bug
>Submitter-Id:   current-users
>Arrival-Date:   Tue Dec 07 21:10:23 GMT 2004
>Closed-Date:
>Last-Modified:
>Originator:     Mike Tancsa
>Release:        RELENG_5
>Organization:
Sentex Communications
>Environment:
FreeBSD releng5-865.sentex.ca 5.3-STABLE FreeBSD 5.3-STABLE #0: Tue Dec  7 11:29:41 EST 2004 
>Description:
When enabling LQR on FreeBSD with PPPoE, and when the otherside is a Juniper ERX, LQM_LQR does not seem to work properly... However, LQM_ECHO does seem to work. 

Here is a sample broken session

Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: Phase: deflink: his = PAP, mine = none
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: Phase: Pap Output: testusername@sentex.ca ********
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: Phase: Pap Input: SUCCESS ()
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: IPCP: Using trigger address 0.0.0.0
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: CCP: FSM: Using "deflink" as a transport
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: CCP: deflink: State change Initial --> Closed
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: CCP: deflink: LayerStart.
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: CCP: MPPE: Not usable without CHAP81
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: CCP: deflink: SendConfigReq(1) state = Closed
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: CCP:  DEFLATE[4] win 15
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: CCP:  PRED1[2] 
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: CCP: deflink: State change Closed --> Req-Sent
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: Phase: deflink: lcp -> open
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: Phase: bundle: Network
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: IPCP: FSM: Using "deflink" as a transport
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: IPCP: deflink: State change Initial --> Closed
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: IPCP: deflink: LayerStart.
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: IPCP: deflink: SendConfigReq(9) state = Closed
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: IPCP:  IPADDR[6] 0.0.0.0
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: IPCP:  PRIDNS[6] 205.211.164.51
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: IPCP:  SECDNS[6] 64.7.128.99
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: IPCP: deflink: State change Closed --> Req-Sent
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: IPCP: deflink: RecvConfigReq(1) state = Req-Sent
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: IPCP:  IPADDR[6] 67.43.128.6
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: IPCP: deflink: SendConfigAck(1) state = Req-Sent
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: IPCP:  IPADDR[6] 67.43.128.6
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: IPCP: deflink: State change Req-Sent --> Ack-Sent
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: LCP: deflink: RecvProtocolRej(3) state = Opened
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: LCP: deflink: -- Protocol 0x80fd (Compression Control Protocol) was rejected!
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: CCP: deflink: State change Req-Sent --> Stopped
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: IPCP: deflink: RecvConfigNak(9) state = Ack-Sent
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: IPCP:  IPADDR[6] 67.43.133.120
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: IPCP:  IPADDR[6] changing address: 0.0.0.0  --> 67.43.133.120
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: IPCP: deflink: SendConfigReq(10) state = Ack-Sent
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: IPCP:  IPADDR[6] 67.43.133.120
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: IPCP:  PRIDNS[6] 205.211.164.51
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: IPCP:  SECDNS[6] 64.7.128.99
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: IPCP: deflink: RecvConfigAck(10) state = Ack-Sent
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: IPCP:  IPADDR[6] 67.43.133.120
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: IPCP:  PRIDNS[6] 205.211.164.51
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: IPCP:  SECDNS[6] 64.7.128.99
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: IPCP: deflink: State change Ack-Sent --> Opened
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: IPCP: deflink: LayerUp.
Dec  7 15:58:39 releng5-865 ppp[4420]: tun0: IPCP: myaddr 67.43.133.120 hisaddr = 67.43.128.6
Dec  7 15:58:40 releng5-865 ppp[4420]: tun0: LCP: deflink: RecvEchoRequest(1) state = Opened
Dec  7 15:58:40 releng5-865 ppp[4420]: tun0: LCP: deflink: SendEchoReply(1) state = Opened
Dec  7 15:58:49 releng5-865 ppp[4420]: tun0: LQM: deflink: Output:
Dec  7 15:58:49 releng5-865 ppp[4420]: tun0: LQM:   Magic:          24f33001   LastOutLQRs:    00000000
Dec  7 15:58:49 releng5-865 ppp[4420]: tun0: LQM:   LastOutPackets: 00000000   LastOutOctets:  00000000
Dec  7 15:58:49 releng5-865 ppp[4420]: tun0: LQM:   PeerInLQRs:     00000000   PeerInPackets:  00000000
Dec  7 15:58:49 releng5-865 ppp[4420]: tun0: LQM:   PeerInDiscards: 00000000   PeerInErrors:   00000000
Dec  7 15:58:49 releng5-865 ppp[4420]: tun0: LQM:   PeerInOctets:   00000000   PeerOutLQRs:    00000002
Dec  7 15:58:49 releng5-865 ppp[4420]: tun0: LQM:   PeerOutPackets: 0000001a   PeerOutOctets:  000002ce
Dec  7 15:58:50 releng5-865 ppp[4420]: tun0: LCP: deflink: RecvEchoRequest(2) state = Opened
Dec  7 15:58:50 releng5-865 ppp[4420]: tun0: LCP: deflink: SendEchoReply(2) state = Opened
Dec  7 15:58:59 releng5-865 ppp[4420]: tun0: LQM: deflink: Output:
Dec  7 15:58:59 releng5-865 ppp[4420]: tun0: LQM:   Magic:          24f33001   LastOutLQRs:    00000000
Dec  7 15:58:59 releng5-865 ppp[4420]: tun0: LQM:   LastOutPackets: 00000000   LastOutOctets:  00000000
Dec  7 15:58:59 releng5-865 ppp[4420]: tun0: LQM:   PeerInLQRs:     00000000   PeerInPackets:  00000000
Dec  7 15:58:59 releng5-865 ppp[4420]: tun0: LQM:   PeerInDiscards: 00000000   PeerInErrors:   00000000
Dec  7 15:58:59 releng5-865 ppp[4420]: tun0: LQM:   PeerInOctets:   00000000   PeerOutLQRs:    00000003
Dec  7 15:58:59 releng5-865 ppp[4420]: tun0: LQM:   PeerOutPackets: 0000001c   PeerOutOctets:  00000310
Dec  7 15:59:00 releng5-865 ppp[4420]: tun0: LCP: deflink: RecvEchoRequest(3) state = Opened
Dec  7 15:59:00 releng5-865 ppp[4420]: tun0: LCP: deflink: SendEchoReply(3) state = Opened
Dec  7 15:59:09 releng5-865 ppp[4420]: tun0: LQM: deflink: Output:
Dec  7 15:59:09 releng5-865 ppp[4420]: tun0: LQM:   Magic:          24f33001   LastOutLQRs:    00000000
Dec  7 15:59:09 releng5-865 ppp[4420]: tun0: LQM:   LastOutPackets: 00000000   LastOutOctets:  00000000
Dec  7 15:59:09 releng5-865 ppp[4420]: tun0: LQM:   PeerInLQRs:     00000000   PeerInPackets:  00000000
Dec  7 15:59:09 releng5-865 ppp[4420]: tun0: LQM:   PeerInDiscards: 00000000   PeerInErrors:   00000000
Dec  7 15:59:09 releng5-865 ppp[4420]: tun0: LQM:   PeerInOctets:   00000000   PeerOutLQRs:    00000004
Dec  7 15:59:09 releng5-865 ppp[4420]: tun0: LQM:   PeerOutPackets: 0000001e   PeerOutOctets:  00000352
Dec  7 15:59:10 releng5-865 ppp[4420]: tun0: LCP: deflink: RecvEchoRequest(4) state = Opened
Dec  7 15:59:10 releng5-865 ppp[4420]: tun0: LCP: deflink: SendEchoReply(4) state = Opened
Dec  7 15:59:19 releng5-865 ppp[4420]: tun0: LQM: deflink: Output:
Dec  7 15:59:19 releng5-865 ppp[4420]: tun0: LQM:   Magic:          24f33001   LastOutLQRs:    00000000
Dec  7 15:59:19 releng5-865 ppp[4420]: tun0: LQM:   LastOutPackets: 00000000   LastOutOctets:  00000000
Dec  7 15:59:19 releng5-865 ppp[4420]: tun0: LQM:   PeerInLQRs:     00000000   PeerInPackets:  00000000
Dec  7 15:59:19 releng5-865 ppp[4420]: tun0: LQM:   PeerInDiscards: 00000000   PeerInErrors:   00000000
Dec  7 15:59:19 releng5-865 ppp[4420]: tun0: LQM:   PeerInOctets:   00000000   PeerOutLQRs:    00000005
Dec  7 15:59:19 releng5-865 ppp[4420]: tun0: LQM:   PeerOutPackets: 00000020   PeerOutOctets:  00000394
Dec  7 15:59:21 releng5-865 ppp[4420]: tun0: LCP: deflink: RecvEchoRequest(5) state = Opened
Dec  7 15:59:21 releng5-865 ppp[4420]: tun0: LCP: deflink: SendEchoReply(5) state = Opened
Dec  7 15:59:30 releng5-865 ppp[4420]: tun0: LQM: deflink: Output:
Dec  7 15:59:30 releng5-865 ppp[4420]: tun0: LQM:   Magic:          24f33001   LastOutLQRs:    00000000
Dec  7 15:59:30 releng5-865 ppp[4420]: tun0: LQM:   LastOutPackets: 00000000   LastOutOctets:  00000000
Dec  7 15:59:30 releng5-865 ppp[4420]: tun0: LQM:   PeerInLQRs:     00000000   PeerInPackets:  00000000
Dec  7 15:59:30 releng5-865 ppp[4420]: tun0: LQM:   PeerInDiscards: 00000000   PeerInErrors:   00000000
Dec  7 15:59:30 releng5-865 ppp[4420]: tun0: LQM:   PeerInOctets:   00000000   PeerOutLQRs:    00000006
Dec  7 15:59:30 releng5-865 ppp[4420]: tun0: LQM:   PeerOutPackets: 00000022   PeerOutOctets:  000003d6
Dec  7 15:59:31 releng5-865 ppp[4420]: tun0: LCP: deflink: RecvEchoRequest(6) state = Opened
Dec  7 15:59:31 releng5-865 ppp[4420]: tun0: LCP: deflink: SendEchoReply(6) state = Opened
Dec  7 15:59:40 releng5-865 ppp[4420]: tun0: Phase: deflink: ** Too many LQR packets lost **
Dec  7 15:59:40 releng5-865 ppp[4420]: tun0: LQM: deflink: Too many LQR packets lost
Dec  7 15:59:40 releng5-865 ppp[4420]: tun0: CCP: deflink: State change Stopped --> Closed
Dec  7 15:59:40 releng5-865 ppp[4420]: tun0: CCP: deflink: State change Closed --> Initial
Dec  7 15:59:40 releng5-865 ppp[4420]: tun0: LCP: deflink: LayerDown
Dec  7 15:59:40 releng5-865 ppp[4420]: tun0: LCP: deflink: State change Opened --> Starting
Dec  7 15:59:40 releng5-865 ppp[4420]: tun0: Phase: deflink: open -> lcp


Then, forcing LQM_ECHO, it works


>How-To-Repeat:
In Canada, the incumbant telco (Bell Canada) has mostly ERXes deployed.  Enable LQR on the link and you will see it fail.

>Fix:
I came up with this simple hack that lets the user LQM_ECHO in the ppp.conf

releng5-865# diff -u command.c.prev command.c
--- command.c.prev      Tue Dec  7 15:43:28 2004
+++ command.c   Tue Dec  7 15:43:36 2004
@@ -166,6 +166,7 @@
 #define NEG_VJCOMP     53
 #define NEG_MPPE       54
 #define NEG_CHAP81     55
+#define NEG_LCPECHO            56
 
 const char Version[] = "3.2";
 
@@ -2856,6 +2857,10 @@
       cx->physical->link.lcp.cfg.lqr &= keep;
       cx->physical->link.lcp.cfg.lqr |= add;
       break;
+    case NEG_LCPECHO:
+      cx->physical->link.lcp.cfg.forcelcpecho &= keep;
+      cx->physical->link.lcp.cfg.forcelcpecho |= add;
+      break;
     case NEG_PAP:
       cx->physical->link.lcp.cfg.pap &= keep;
       cx->physical->link.lcp.cfg.pap |= add;
@@ -2977,6 +2982,9 @@
   {"lqr", NULL, NegotiateSet, LOCAL_AUTH | LOCAL_CX,
   "Link Quality Reports", "accept|deny|disable|enable",
   (const void *)NEG_LQR},
+  {"forcelcpecho", NULL, NegotiateSet, LOCAL_AUTH | LOCAL_CX,
+  "Link Quality Reports", "accept|deny|disable|enable",
+  (const void *)NEG_LCPECHO},
   {"pap", NULL, NegotiateSet, LOCAL_AUTH | LOCAL_CX,
   "Password Authentication protocol", "accept|deny|disable|enable",
   (const void *)NEG_PAP},
releng5-865# 
releng5-865# diff -u lcp.h.prev lcp.h
--- lcp.h.prev  Tue Dec  7 15:44:04 2004
+++ lcp.h       Tue Dec  7 15:51:21 2004
@@ -98,6 +98,7 @@
     unsigned chap81 : 2;       /* Microsoft CHAP v2 */
 #endif
     unsigned lqr : 2;          /* Link Quality Report */
+    unsigned forcelcpecho : 2;         /* Some PPPoE concentrators are broken for LQR. Allow users to force LCP ECHOS */
     unsigned pap : 2;          /* Password Authentication protocol */
     unsigned protocomp : 2;    /* Protocol field compression */
     char ident[DEF_MRU - 7];   /* SendIdentification() data */
releng5-865# 

releng5-865# diff -u lqr.c.prev lqr.c
--- lqr.c.prev  Tue Dec  7 15:43:34 2004
+++ lqr.c       Tue Dec  7 15:43:36 2004
@@ -276,8 +276,13 @@
          sizeof physical->hdlc.lqm.lqr.peer);
 
   physical->hdlc.lqm.method = LQM_ECHO;
-  if (IsEnabled(lcp->cfg.lqr) && !REJECTED(lcp, TY_QUALPROTO))
+  log_Printf(LogPHASE, "Enabling LQM_ECHO %s",physical->link.name);
+  if (IsEnabled(lcp->cfg.lqr) && !REJECTED(lcp, TY_QUALPROTO) && !IsEnabled(lcp->cfg.forcelcpecho) )
+ {
     physical->hdlc.lqm.method |= LQM_LQR;
+    log_Printf(LogPHASE, "Enabling LQM_LQR, not LQM_ECHO %s",physical->link.name);
+    
+ }
   timer_Stop(&physical->hdlc.lqm.timer);
 
   physical->hdlc.lqm.lqr.peer_timeout = lcp->his_lqrperiod;
releng5-865# 


In /etc/ppp/ppp.conf

the user just needs to add

 enable forcelcpecho

>Release-Note:
>Audit-Trail:
>Unformatted:



Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?200412072106.iB7L6tZr039841>