Bug 81390

Summary:	( usermode ppp ) LCP Negotiation Never Finishes, one of the sides never transmit an ack
Product:	Base System	Reporter:	Rayene Ben Rayana <rayene.benrayana>
Component:	bin	Assignee:	freebsd-bugs (Nobody) <bugs>
Status:	Closed FIXED
Severity:	Affects Only Me
Priority:	Normal
Version:	Unspecified
Hardware:	Any
OS:	Any

Description Rayene Ben Rayana 2005-05-23 10:20:01 UTC

      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 !!

Comment 1 Mark Linimon freebsd_committer

2005-07-23 00:01:29 UTC

Responsible Changed
From-To: freebsd-i386->freebsd-bugs

This does not sound i386-specific.

Comment 2 Matteo Riondato freebsd_committer

2007-03-23 11:06:24 UTC

State Changed
From-To: open->closed

Duplicate of bin/81389