Date: Mon, 23 May 2005 09:15:25 GMT From: Rayene Ben Rayana <rayene.benrayana@topnet.tn> To: freebsd-gnats-submit@FreeBSD.org Subject: i386/81390: ( usermode ppp ) LCP Negotiation Never Finishes, one of the sides never transmit an ack Message-ID: <200505230915.j4N9FPAx022401@www.freebsd.org> Resent-Message-ID: <200505230920.j4N9K2D7093232@freefall.freebsd.org>
next in thread | raw e-mail | index | archive | help
>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@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:
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?200505230915.j4N9FPAx022401>