Bug 29277

Summary: PPPoE weirdness with some DSL providers
Product: Base System Reporter: sw <sw>
Component: binAssignee: Brian Somers <brian>
Status: Closed FIXED    
Severity: Affects Only Me    
Priority: Normal    
Version: 5.0-CURRENT   
Hardware: Any   
OS: Any   

Description sw 2001-07-28 16:50:01 UTC
	PPPoE ADSL connection with PPP loops, and finally gives up:

Jul 22 18:27:15 core ppp[7855]: tun0: LCP: FSM: Using "deflink" as a transport 
Jul 22 18:27:15 core ppp[7855]: tun0: LCP: deflink: State change Initial --> Closed 
Jul 22 18:27:15 core ppp[7855]: tun0: LCP: deflink: State change Closed --> Stopped 
Jul 22 18:27:15 core ppp[7855]: tun0: LCP: deflink: RecvConfigReq(160) state = Stopped 
Jul 22 18:27:15 core ppp[7855]: tun0: LCP:  MRU[4] 1492 
Jul 22 18:27:15 core ppp[7855]: tun0: LCP:  AUTHPROTO[5] 0xc223 (CHAP 0x05) 
Jul 22 18:27:15 core ppp[7855]: tun0: LCP:  MAGICNUM[6] 0x0a29f23b 
Jul 22 18:27:15 core ppp[7855]: tun0: LCP: deflink: SendConfigReq(1) state = Stopped 
Jul 22 18:27:15 core ppp[7855]: tun0: LCP:  MRU[4] 1492 
Jul 22 18:27:15 core ppp[7855]: tun0: LCP:  MAGICNUM[6] 0x42d536c0 
Jul 22 18:27:15 core ppp[7855]: tun0: LCP:  QUALPROTO[8] proto c025, interval 30000ms 
Jul 22 18:27:15 core ppp[7855]: tun0: LCP: deflink: SendConfigAck(160) state = Stopped 
Jul 22 18:27:15 core ppp[7855]: tun0: LCP:  MRU[4] 1492 
Jul 22 18:27:15 core ppp[7855]: tun0: LCP:  AUTHPROTO[5] 0xc223 (CHAP 0x05) 
Jul 22 18:27:15 core ppp[7855]: tun0: LCP:  MAGICNUM[6] 0x0a29f23b 
Jul 22 18:27:15 core ppp[7855]: tun0: LCP: deflink: LayerStart 
Jul 22 18:27:15 core ppp[7855]: tun0: LCP: deflink: State change Stopped --> Ack-Sent 
Jul 22 18:27:15 core ppp[7855]: tun0: LCP: deflink: RecvConfigRej(1) state = Ack-Sent 
Jul 22 18:27:15 core ppp[7855]: tun0: LCP:  QUALPROTO[8] proto c025, interval 30000ms 
Jul 22 18:27:15 core ppp[7855]: tun0: LCP: deflink: SendConfigReq(2) state = Ack-Sent 
Jul 22 18:27:15 core ppp[7855]: tun0: LCP:  MRU[4] 1492 
Jul 22 18:27:15 core ppp[7855]: tun0: LCP:  MAGICNUM[6] 0x42d536c0 
Jul 22 18:27:16 core ppp[7855]: tun0: LCP: deflink: RecvConfigAck(2) state = Ack-Sent 
Jul 22 18:27:16 core ppp[7855]: tun0: LCP: deflink: State change Ack-Sent --> Opened 
Jul 22 18:27:16 core ppp[7855]: tun0: LCP: deflink: LayerUp 
Jul 22 18:27:16 core ppp[7855]: tun0: LCP: deflink: SendEchoRequest(0) state = Opened 
Jul 22 18:27:16 core ppp[7855]: tun0: Phase: bundle: Authenticate 
Jul 22 18:27:16 core ppp[7855]: tun0: Phase: deflink: his = CHAP 0x05, mine = none 
Jul 22 18:27:16 core ppp[7855]: tun0: Phase: Chap Input: CHALLENGE (16 bytes from BSBGN103) 
Jul 22 18:27:16 core ppp[7855]: tun0: Phase: Chap Output: RESPONSE (sameh@net1.nerim.fsa) 
Jul 22 18:27:16 core ppp[7855]: tun0: LCP: deflink: RecvEchoReply(0) state = Opened 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP: deflink: RecvConfigReq(1) state = Opened 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP: deflink: LayerDown 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  AUTHPROTO[5] 0xc223 (CHAP 0x05) 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  MAGICNUM[6] 0x0ecf65f1 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP: deflink: SendConfigReq(3) state = Opened 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  MRU[4] 1492 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  MAGICNUM[6] 0x9429fe39 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  QUALPROTO[8] proto c025, interval 30000ms 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP: deflink: SendConfigNak(1) state = Opened 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  MRU[4] 1492 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP: deflink: State change Opened --> Req-Sent 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP: deflink: RecvConfigNak(3) state = Req-Sent 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  MRU[4] 1500 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP: deflink: SendConfigReq(4) state = Req-Sent 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  MRU[4] 1492 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  MAGICNUM[6] 0x9429fe39 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  QUALPROTO[8] proto c025, interval 30000ms 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP: deflink: RecvConfigReq(2) state = Req-Sent 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  MRU[4] 1492 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  AUTHPROTO[5] 0xc223 (CHAP 0x05) 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  MAGICNUM[6] 0x0ecf65f1 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP: deflink: SendConfigAck(2) state = Req-Sent 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  MRU[4] 1492 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  AUTHPROTO[5] 0xc223 (CHAP 0x05) 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  MAGICNUM[6] 0x0ecf65f1 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP: deflink: State change Req-Sent --> Ack-Sent 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP: deflink: RecvConfigNak(4) state = Ack-Sent 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  MRU[4] 1500 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP: deflink: SendConfigReq(5) state = Ack-Sent 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  MRU[4] 1492 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  MAGICNUM[6] 0x9429fe39 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  QUALPROTO[8] proto c025, interval 30000ms 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP: deflink: RecvConfigNak(5) state = Ack-Sent 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  MRU[4] 1500 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP: deflink: SendConfigReq(6) state = Ack-Sent 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  MRU[4] 1492 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  MAGICNUM[6] 0x9429fe39 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  QUALPROTO[8] proto c025, interval 30000ms 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP: deflink: RecvConfigNak(6) state = Ack-Sent 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  MRU[4] 1500 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP: deflink: SendConfigReq(7) state = Ack-Sent 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  MRU[4] 1492 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  MAGICNUM[6] 0x9429fe39 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  QUALPROTO[8] proto c025, interval 30000ms 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP: deflink: RecvConfigNak(7) state = Ack-Sent 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  MRU[4] 1500 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP: deflink: SendConfigReq(8) state = Ack-Sent 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  MRU[4] 1492 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  MAGICNUM[6] 0x9429fe39 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  QUALPROTO[8] proto c025, interval 30000ms 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP: deflink: RecvConfigRej(8) state = Ack-Sent 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  MRU[4] 1492 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP: deflink: SendConfigReq(9) state = Ack-Sent 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  MRU[4] 1492 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  MAGICNUM[6] 0x9429fe39 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  QUALPROTO[8] proto c025, interval 30000ms 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP: deflink: RecvConfigRej(9) state = Ack-Sent 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  MRU[4] 1492 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP: deflink: SendConfigReq(10) state = Ack-Sent 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  MRU[4] 1492 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  MAGICNUM[6] 0x9429fe39 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  QUALPROTO[8] proto c025, interval 30000ms 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP: deflink: RecvConfigRej(10) state = Ack-Sent 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  MRU[4] 1492 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP: deflink: SendConfigReq(11) state = Ack-Sent 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  MRU[4] 1492 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  MAGICNUM[6] 0x9429fe39 
Jul 22 18:27:18 core ppp[7855]: tun0: LCP:  QUALPROTO[8] proto c025, interval 30000ms 
Jul 22 18:27:19 core ppp[7855]: tun0: LCP: deflink: RecvConfigRej(11) state = Ack-Sent 
Jul 22 18:27:19 core ppp[7855]: tun0: LCP:  MRU[4] 1492 
Jul 22 18:27:19 core ppp[7855]: tun0: LCP: deflink: SendConfigReq(12) state = Ack-Sent 
Jul 22 18:27:19 core ppp[7855]: tun0: LCP:  MRU[4] 1492 
Jul 22 18:27:19 core ppp[7855]: tun0: LCP:  MAGICNUM[6] 0x9429fe39 
Jul 22 18:27:19 core ppp[7855]: tun0: LCP:  QUALPROTO[8] proto c025, interval 30000ms 
Jul 22 18:27:19 core ppp[7855]: tun0: LCP: deflink: RecvConfigRej(12) state = Ack-Sent 
Jul 22 18:27:19 core ppp[7855]: tun0: LCP:  MRU[4] 1492 
Jul 22 18:27:19 core ppp[7855]: tun0: LCP: deflink: SendConfigReq(13) state = Ack-Sent 
Jul 22 18:27:19 core ppp[7855]: tun0: LCP:  MRU[4] 1492 
Jul 22 18:27:19 core ppp[7855]: tun0: LCP:  MAGICNUM[6] 0x9429fe39 
Jul 22 18:27:19 core ppp[7855]: tun0: LCP:  QUALPROTO[8] proto c025, interval 30000ms 
Jul 22 18:27:19 core ppp[7855]: tun0: LCP: deflink: RecvConfigRej(13) state = Ack-Sent 
Jul 22 18:27:19 core ppp[7855]: tun0: LCP:  MRU[4] 1492 
Jul 22 18:27:19 core ppp[7855]: tun0: LCP: deflink: SendConfigReq(14) state = Ack-Sent 
Jul 22 18:27:19 core ppp[7855]: tun0: LCP:  MRU[4] 1492 
Jul 22 18:27:19 core ppp[7855]: tun0: LCP:  MAGICNUM[6] 0x9429fe39 
Jul 22 18:27:19 core ppp[7855]: tun0: LCP:  QUALPROTO[8] proto c025, interval 30000ms 
Jul 22 18:27:19 core ppp[7855]: tun0: LCP: deflink: RecvConfigRej(14) state = Ack-Sent 
Jul 22 18:27:19 core ppp[7855]: tun0: LCP:  MRU[4] 1492 
Jul 22 18:27:19 core ppp[7855]: tun0: LCP: deflink: SendConfigReq(15) state = Ack-Sent 
Jul 22 18:27:19 core ppp[7855]: tun0: LCP:  MRU[4] 1492 
Jul 22 18:27:19 core ppp[7855]: tun0: LCP:  MAGICNUM[6] 0x9429fe39 
Jul 22 18:27:19 core ppp[7855]: tun0: LCP:  QUALPROTO[8] proto c025, interval 30000ms 
Jul 22 18:27:19 core ppp[7855]: tun0: LCP: deflink: RecvConfigRej(15) state = Ack-Sent 
Jul 22 18:27:19 core ppp[7855]: tun0: LCP:  MRU[4] 1492 
Jul 22 18:27:19 core ppp[7855]: tun0: LCP: deflink: SendConfigReq(16) state = Ack-Sent 
Jul 22 18:27:19 core ppp[7855]: tun0: LCP:  MRU[4] 1492 
Jul 22 18:27:19 core ppp[7855]: tun0: LCP:  MAGICNUM[6] 0x9429fe39 
Jul 22 18:27:19 core ppp[7855]: tun0: LCP:  QUALPROTO[8] proto c025, interval 30000ms 
Jul 22 18:27:19 core ppp[7855]: tun0: LCP: deflink: RecvConfigRej(16) state = Ack-Sent 
Jul 22 18:27:19 core ppp[7855]: tun0: LCP:  MRU[4] 1492 
Jul 22 18:27:19 core ppp[7855]: tun0: LCP: deflink: SendConfigReq(17) state = Ack-Sent 
Jul 22 18:27:19 core ppp[7855]: tun0: LCP:  MRU[4] 1492 
Jul 22 18:27:19 core ppp[7855]: tun0: LCP:  MAGICNUM[6] 0x9429fe39 
Jul 22 18:27:19 core ppp[7855]: tun0: LCP:  QUALPROTO[8] proto c025, interval 30000ms 
Jul 22 18:27:19 core ppp[7855]: tun0: LCP: deflink: RecvConfigRej(17) state = Ack-Sent 
Jul 22 18:27:19 core ppp[7855]: tun0: LCP:  MRU[4] 1492 
Jul 22 18:27:19 core ppp[7855]: tun0: Phase: deflink: Too many LCP REQs sent - abandoning negotiation 

The problem does not happen with an old release PPP. It also happens only with *some* DSL providers.

It has been seen with Nerim, by two others french -STABLE users, after a PPP upgrade. A PPP downgrade fixes
the problem.

Removing set mru/mtu from ppp.conf doesn't resolve the problem.

Fix: 

Must have something with the ether.c/lcp.c commits around 18th-20th July.
	Please contact me to test patches if you have some.
How-To-Repeat: 
Try connecting with a fresh -current or -stable to some DSL providers, using PPPoE.
Comment 1 Mike Barcroft freebsd_committer freebsd_triage 2001-07-30 04:15:16 UTC
Responsible Changed
From-To: freebsd-bugs->brian


Over to maintainer.
Comment 2 Brian Somers 2001-07-30 18:03:07 UTC
> >Number:         29277
> >Category:       bin
> >Synopsis:       PPPoE weirdness with some DSL providers

This seems to be a bug in win2k.  The attached patch allows 
negotiation to continue after win2k starts REJecting the MRU option, 
but I don't know if this results in win2k using the wrong MTU.

-- 
Brian <brian@freebsd-services.com>                <brian@Awfulhak.org>
      http://www.freebsd-services.com/        <brian@[uk.]FreeBSD.org>
Don't _EVER_ lose your sense of humour !      <brian@[uk.]OpenBSD.org>

Index: lcp.c
===================================================================
RCS file: /home/ncvs/src/usr.sbin/ppp/lcp.c,v
retrieving revision 1.93
diff -u -r1.93 lcp.c
--- lcp.c	2001/07/26 11:33:53	1.93
+++ lcp.c	2001/07/30 15:20:43
@@ -408,7 +408,7 @@
                fp->link->name, lcp->want_mru, maxmru);
     lcp->want_mru = maxmru;
   }
-  if (!REJECTED(lcp, TY_MRU) || lcp->want_mru < DEF_MRU) {
+  if (!REJECTED(lcp, TY_MRU)) {
     ua_htons(&lcp->want_mru, o->data);
     INC_LCP_OPT(TY_MRU, 4, o);
   }
Comment 3 Brian Somers freebsd_committer freebsd_triage 2001-08-01 22:22:55 UTC
State Changed
From-To: open->closed

Fixed in -stable (lcp.c version 1.81.2.10)