i386/81390: ( usermode ppp ) LCP Negotiation Never Finishes, one of the sides never transmit an ack

Rayene Ben Rayana rayene.benrayana at topnet.tn
Mon May 23 09:20:03 GMT 2005 

>Number:         81390
>Category:       i386
>Synopsis:       ( usermode ppp ) LCP Negotiation Never Finishes, one of the sides never transmit an ack
>Confidential:   no
>Severity:       serious
>Priority:       high
>Responsible:    freebsd-i386
>State:          open
>Quarter:        
>Keywords:       
>Date-Required:
>Class:          sw-bug
>Submitter-Id:   current-users
>Arrival-Date:   Mon May 23 09:20:01 GMT 2005
>Closed-Date:
>Last-Modified:
>Originator:     Rayene Ben Rayana
>Release:        5.3
>Organization:
ENSI - ENSTB
>Environment:
FreeBSD l2tp-lns 5.3-RELEASE FreeBSD 5.3-RELEASE #0: Fri Nov  5 04:19:18 UTC 2004 root at harlow.cse.buffalo.edu:/usr/obj/usr/src/sys/GENERIC  i386
   
>Description:
      I'm trying to get usermode ppp working over an L2TP tunnel (ppp is started in -direct mode). The problem is that ppp is unable to accomplish LCP negociation (it can rarely do it).

I examined the log Files on the two sides, and here are my conclusions

machine A sends an LCP request (MRU = 1500) (Stopped --7 ReqSent)

After receiving that request, B sends his REQUEST and logs that it has sent an ack to A. (Stopped --7 AckSent).
In reality, It sends only a request (Ethereal Capture).

machine A receives the request and sends an ack (ReqSent --7 AckSent).

machine B receives the ack. (AckSent --7 Opened). It sends an identification.

machine Is still waiting for the Ack --7 Timeout (3 sec by default). (

machine A re-sends a request,

Machine B re-sends a request and an ack (I insist that the ack is not really transmitted, It's ppp.log'd)

And we repeat the same sequence 5 times. (default LCP retries)

In ethereal, I can see :

-------------1st iteration-------------
A to B : LCP Config Request (id = 1)
B to A : LCP Config Request (id = 1)
A to B : LCP Config Ack (id = 1)
B to A : LCP Identification (id = 0)
-------------2nd iteration-------------
A to B : LCP Config Request (id = 1)
B to A : LCP Config Request (id = 2)
A to B : LCP Config Ack (id = 2)
B to A : LCP Identification (id = 1)
-------------3rd iteration-------------
A to B : LCP Config Request (id = 2)
B to A : LCP Config Request (id = 3)
A to B : LCP Config Ack (id = 3)
B to A : LCP Identification (id = 2)
-------------4th iteration-------------
..
-------------5th iteration-------------
..


Here's the Log of machine B (the one that doesn't send the ack) It's seems long but there's repetition.

 May 23 09:46:32 manooba ppp[712]: LCP: FSM: Using  "deflink" as a transport 
 May 23 09:46:32 manooba ppp[712]: LCP: deflink: State  change Initial --> Closed 
 May 23 09:46:32 manooba ppp[712]: LCP: deflink: State  change Closed --> Stopped 
 May 23 09:46:33 manooba ppp[712]: LCP: deflink:  RecvConfigReq(1) state = Stopped 
 May 23 09:46:33 manooba ppp[712]: LCP:  MRU[4] 1500 
 May 23 09:46:33 manooba ppp[712]: LCP:  MAGICNUM[6]  0x18557c3a 
 May 23 09:46:33 manooba ppp[712]: LCP: deflink:  SendConfigReq(1) state = Stopped 
 May 23 09:46:33 manooba ppp[712]: LCP:  MRU[4] 1500 
 May 23 09:46:33 manooba ppp[712]: LCP:  MAGICNUM[6]  0x14d00770 
 May 23 09:46:33 manooba ppp[712]: LCP: deflink:  SendConfigAck(1) state = Stopped 
 May 23 09:46:33 manooba ppp[712]: LCP:  MRU[4] 1500 
 May 23 09:46:33 manooba ppp[712]: LCP:  MAGICNUM[6]  0x18557c3a 
 May 23 09:46:33 manooba ppp[712]: LCP: deflink:  LayerStart 
 May 23 09:46:33 manooba ppp[712]: LCP: deflink: State  change Stopped --> Ack-Sent 
 May 23 09:46:33 manooba ppp[712]: LCP: deflink:  RecvConfigAck(1) state = Ack-Sent 
 May 23 09:46:33 manooba ppp[712]: LCP:  MRU[4] 1500 
 May 23 09:46:33 manooba ppp[712]: LCP:  MAGICNUM[6]  0x14d00770 
 May 23 09:46:33 manooba ppp[712]: LCP: deflink: State  change Ack-Sent --> Opened 
 May 23 09:46:33 manooba ppp[712]: LCP: deflink:  LayerUp 
 May 23 09:46:33 manooba ppp[712]: LCP: deflink:  SendIdent(0) state = Opened 
 May 23 09:46:33 manooba ppp[712]: LCP:  MAGICNUM  14d00770 
 May 23 09:46:33 manooba ppp[712]: LCP:  TEXT user-ppp  3.2 (built Nov  4 2004) 
 May 23 09:46:36 manooba ppp[712]: LCP: deflink:  RecvConfigReq(1) state = Opened 
 May 23 09:46:36 manooba ppp[712]: LCP: deflink:  LayerDown 
 May 23 09:46:36 manooba ppp[712]: LCP:  MRU[4] 1500 
 May 23 09:46:36 manooba ppp[712]: LCP:  MAGICNUM[6]  0x18557c3a 
 May 23 09:46:36 manooba ppp[712]: LCP: deflink:  SendConfigReq(2) state = Opened 
 May 23 09:46:36 manooba ppp[712]: LCP:  MRU[4] 1500 
 May 23 09:46:36 manooba ppp[712]: LCP:  MAGICNUM[6]  0x11b37491 
 May 23 09:46:36 manooba ppp[712]: LCP: deflink:  SendConfigAck(1) state = Opened 
 May 23 09:46:36 manooba ppp[712]: LCP:  MRU[4] 1500 
 May 23 09:46:36 manooba ppp[712]: LCP:  MAGICNUM[6]  0x18557c3a 
 May 23 09:46:36 manooba ppp[712]: LCP: deflink: State  change Opened --> Ack-Sent 
 May 23 09:46:36 manooba ppp[712]: LCP: deflink:  RecvConfigAck(2) state = Ack-Sent 
 May 23 09:46:36 manooba ppp[712]: LCP:  MRU[4] 1500 
 May 23 09:46:36 manooba ppp[712]: LCP:  MAGICNUM[6]  0x11b37491 
 May 23 09:46:36 manooba ppp[712]: LCP: deflink: State  change Ack-Sent --> Opened 
 May 23 09:46:36 manooba ppp[712]: LCP: deflink:  LayerUp 
 May 23 09:46:36 manooba ppp[712]: LCP: deflink:  SendIdent(1) state = Opened 
 May 23 09:46:36 manooba ppp[712]: LCP:  MAGICNUM 11b37491 
 May 23 09:46:36 manooba ppp[712]: LCP:  TEXT user-ppp  3.2 (built Nov  4 2004) 
 May 23 09:46:39 manooba ppp[712]: LCP: deflink:  RecvConfigReq(2) state = Opened 
 May 23 09:46:39 manooba ppp[712]: LCP: deflink:  LayerDown 
 May 23 09:46:39 manooba ppp[712]: LCP:  MRU[4] 1500 
 May 23 09:46:39 manooba ppp[712]: LCP:  MAGICNUM[6]  0x18557c3a 
 May 23 09:46:39 manooba ppp[712]: LCP: deflink:  SendConfigReq(3) state = Opened 
 May 23 09:46:39 manooba ppp[712]: LCP:  MRU[4] 1500 
 May 23 09:46:39 manooba ppp[712]: LCP:  MAGICNUM[6]  0x4e4ac1eb 
 May 23 09:46:39 manooba ppp[712]: LCP: deflink:  SendConfigAck(2) state = Opened 
 May 23 09:46:39 manooba ppp[712]: LCP:  MRU[4] 1500 
 May 23 09:46:39 manooba ppp[712]: LCP:  MAGICNUM[6]  0x18557c3a 
 May 23 09:46:39 manooba ppp[712]: LCP: deflink: State  change Opened --> Ack-Sent 
 May 23 09:46:39 manooba ppp[712]: LCP: deflink:  RecvConfigAck(3) state = Ack-Sent 
 May 23 09:46:39 manooba ppp[712]: LCP:  MRU[4] 1500 
 May 23 09:46:39 manooba ppp[712]: LCP:  MAGICNUM[6]  0x4e4ac1eb 
 May 23 09:46:39 manooba ppp[712]: LCP: deflink: State  change Ack-Sent --> Opened 
 May 23 09:46:39 manooba ppp[712]: LCP: deflink:  LayerUp 
 May 23 09:46:39 manooba ppp[712]: LCP: deflink:  SendIdent(2) state = Opened 
 May 23 09:46:39 manooba ppp[712]: LCP:  MAGICNUM  4e4ac1eb 
 May 23 09:46:39 manooba ppp[712]: LCP:  TEXT user-ppp  3.2 (built Nov  4 2004) 
 May 23 09:46:42 manooba ppp[712]: LCP: deflink:  RecvConfigReq(3) state = Opened 
 May 23 09:46:42 manooba ppp[712]: LCP: deflink:  LayerDown 
 May 23 09:46:42 manooba ppp[712]: LCP:  MRU[4] 1500 
 May 23 09:46:42 manooba ppp[712]: LCP:  MAGICNUM[6]  0x18557c3a 
 May 23 09:46:42 manooba ppp[712]: LCP: deflink:  SendConfigReq(4) state = Opened 
 May 23 09:46:42 manooba ppp[712]: LCP:  MRU[4] 1500 
 May 23 09:46:42 manooba ppp[712]: LCP:  MAGICNUM[6]  0x46fa73b0 
 May 23 09:46:42 manooba ppp[712]: LCP: deflink:  SendConfigAck(3) state = Opened 
 May 23 09:46:42 manooba ppp[712]: LCP:  MRU[4] 1500 
 May 23 09:46:42 manooba ppp[712]: LCP:  MAGICNUM[6]  0x18557c3a 
 May 23 09:46:42 manooba ppp[712]: LCP: deflink: State  change Opened --> Ack-Sent 
 May 23 09:46:42 manooba ppp[712]: LCP: deflink:  RecvConfigAck(4) state = Ack-Sent 
 May 23 09:46:42 manooba ppp[712]: LCP:  MRU[4] 1500 
 May 23 09:46:42 manooba ppp[712]: LCP:  MAGICNUM[6]  0x46fa73b0 
 May 23 09:46:42 manooba ppp[712]: LCP: deflink: State  change Ack-Sent --> Opened 
 May 23 09:46:42 manooba ppp[712]: LCP: deflink:  LayerUp 
 May 23 09:46:42 manooba ppp[712]: LCP: deflink:  SendIdent(3) state = Opened 
 May 23 09:46:42 manooba ppp[712]: LCP:  MAGICNUM  46fa73b0 
 May 23 09:46:42 manooba ppp[712]: LCP:  TEXT user-ppp  3.2 (built Nov  4 2004) 
 May 23 09:46:45 manooba ppp[712]: LCP: deflink:  RecvConfigReq(4) state = Opened 
 May 23 09:46:45 manooba ppp[712]: LCP: deflink:  LayerDown 
 May 23 09:46:45 manooba ppp[712]: LCP:  MRU[4] 1500 
 May 23 09:46:45 manooba ppp[712]: LCP:  MAGICNUM[6]  0x18557c3a 
 May 23 09:46:45 manooba ppp[712]: LCP: deflink:  SendConfigReq(5) state = Opened 
 May 23 09:46:45 manooba ppp[712]: LCP:  MRU[4] 1500 
 May 23 09:46:45 manooba ppp[712]: LCP:  MAGICNUM[6]  0x7885184e 
 May 23 09:46:45 manooba ppp[712]: LCP: deflink:  SendConfigAck(4) state = Opened 
 May 23 09:46:45 manooba ppp[712]: LCP:  MRU[4] 1500 
 May 23 09:46:45 manooba ppp[712]: LCP:  MAGICNUM[6]  0x18557c3a 
 May 23 09:46:45 manooba ppp[712]: LCP: deflink: State  change Opened --> Ack-Sent 
 May 23 09:46:45 manooba ppp[712]: LCP: deflink:  RecvConfigAck(5) state = Ack-Sent 
 May 23 09:46:45 manooba ppp[712]: LCP:  MRU[4] 1500 
 May 23 09:46:45 manooba ppp[712]: LCP:  MAGICNUM[6]  0x7885184e 
 May 23 09:46:45 manooba ppp[712]: LCP: deflink: State  change Ack-Sent --> Opened 
 May 23 09:46:45 manooba ppp[712]: LCP: deflink:  LayerUp 
 May 23 09:46:45 manooba ppp[712]: LCP: deflink:  SendIdent(4) state = Opened 
 May 23 09:46:45 manooba ppp[712]: LCP:  MAGICNUM  7885184e 
 May 23 09:46:45 manooba ppp[712]: LCP:  TEXT user-ppp  3.2 (built Nov  4 2004) 
 May 23 09:46:48 manooba ppp[712]: LCP: deflink:  LayerDown 
 May 23 09:46:48 manooba ppp[712]: LCP: deflink: State  change Opened --> Starting 
 May 23 09:46:48 manooba ppp[712]: LCP: deflink:  LayerFinish 
 May 23 09:46:48 manooba ppp[712]: LCP: deflink: State  change Starting --> Initial 

>How-To-Repeat:
       
 Just Initiate an L2TP tunnel with the peer. The l2tpd daemon will call the ppp and In, 90% of the cases, the same bug.

Sometimes It works (B sends an Ack) This happens when IPCP or IPv6CP packets are sent between LCP ones. Strange !!
>Fix:
      
>Release-Note:
>Audit-Trail:
>Unformatted:

More information about the freebsd-i386 mailing list