Date: Mon, 23 May 2005 09:11:10 GMT From: Rayene Ben Rayana <rayene.benrayana@topnet.tn> To: freebsd-gnats-submit@FreeBSD.org Subject: gnu/81389: ( usermode ppp ) LCP Negotiation Never Finishes, one of the sides never transmit an ackppp Message-ID: <200505230911.j4N9BAi0021386@www.freebsd.org> Resent-Message-ID: <200505230920.j4N9K1K3093175@freefall.freebsd.org>
next in thread | raw e-mail | index | archive | help
>Number: 81389 >Category: gnu >Synopsis: ( usermode ppp ) LCP Negotiation Never Finishes, one of the sides never transmit an ackppp >Confidential: no >Severity: serious >Priority: high >Responsible: freebsd-bugs >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 >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?200505230911.j4N9BAi0021386>