Bug 81389

Summary: ( usermode ppp ) LCP Negotiation Never Finishes, one of the sides never transmit an ackppp
Product: Base System Reporter: Rayene Ben Rayana <rayene.benrayana>
Component: binAssignee: Brian Somers <brian>
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 Gleb Smirnoff freebsd_committer freebsd_triage 2005-05-23 14:32:59 UTC 
Responsible Changed
From-To: freebsd-bugs->brian

Over to ppp(8) maintainer.
Comment 2 Brian Somers freebsd_committer freebsd_triage 2005-05-23 16:59:18 UTC 
On Mon, 23 May 2005 13:33:25 GMT, Gleb Smirnoff <glebius@FreeBSD.org> wrote:
> Synopsis: ( usermode ppp ) LCP Negotiation Never Finishes, one of the sides never transmit an ackppp
> 
> Responsible-Changed-From-To: freebsd-bugs->brian
> Responsible-Changed-By: glebius
> Responsible-Changed-When: Mon May 23 13:32:59 GMT 2005
> Responsible-Changed-Why: 
> Over to ppp(8) maintainer.
> 
> http://www.freebsd.org/cgi/query-pr.cgi?pr=81389

Can the originator enable physical logging (set log +physical)?  This
should determine if ppp(8) is actually write(2)ing the data.

I suspect it is.  Perhaps the l2tp software is masking the ACKs for
some reason?

-- 
Brian Somers                                          <brian@Awfulhak.org>
Don't _EVER_ lose your sense of humour !               <brian@FreeBSD.org>
Comment 3 Brian Somers freebsd_committer freebsd_triage 2009-05-29 07:29:47 UTC 
State Changed
From-To: open->feedback

I'm 5 years late in responding here.... it's a long shot, 
but maybe the originator can still reproduce this? 

If so, is it possible to "set log +physical +debug" to 
show what's going on with that LCP ACK?  The only thing 
I can come up with right now is that the L2TP tunnel is 
not 8-bit clean and we need to 'set escape' in ppp to 
get the LCP conversation to complete. 

If the logs for both ends are available (assuming they're 
both ppp(8)), it'll give more insight... 

Thanks.
Comment 4 Brian Somers freebsd_committer freebsd_triage 2009-07-18 22:41:31 UTC 
State Changed
From-To: feedback->closed

No response from the submitter in over 7 weeks.  This *may* be a problem 
that can be resolved with some configuration adjustments, but I'm not sure 
and can't do more without additional feedback.