From owner-freebsd-i386@FreeBSD.ORG Mon May 23 09:20:02 2005 Return-Path: X-Original-To: freebsd-i386@hub.freebsd.org Delivered-To: freebsd-i386@hub.freebsd.org Received: from mx1.FreeBSD.org (mx1.freebsd.org [216.136.204.125]) by hub.freebsd.org (Postfix) with ESMTP id ED30F16A41F for ; Mon, 23 May 2005 09:20:02 +0000 (GMT) (envelope-from gnats@FreeBSD.org) Received: from freefall.freebsd.org (freefall.freebsd.org [216.136.204.21]) by mx1.FreeBSD.org (Postfix) with ESMTP id 5F0D643D1D for ; Mon, 23 May 2005 09:20:02 +0000 (GMT) (envelope-from gnats@FreeBSD.org) Received: from freefall.freebsd.org (gnats@localhost [127.0.0.1]) by freefall.freebsd.org (8.13.3/8.13.3) with ESMTP id j4N9K2sI093233 for ; Mon, 23 May 2005 09:20:02 GMT (envelope-from gnats@freefall.freebsd.org) Received: (from gnats@localhost) by freefall.freebsd.org (8.13.3/8.13.1/Submit) id j4N9K2D7093232; Mon, 23 May 2005 09:20:02 GMT (envelope-from gnats) Resent-Date: Mon, 23 May 2005 09:20:02 GMT Resent-Message-Id: <200505230920.j4N9K2D7093232@freefall.freebsd.org> Resent-From: FreeBSD-gnats-submit@FreeBSD.org (GNATS Filer) Resent-To: freebsd-i386@FreeBSD.org Resent-Reply-To: FreeBSD-gnats-submit@FreeBSD.org, Rayene Ben Rayana Received: from mx1.FreeBSD.org (mx1.freebsd.org [216.136.204.125]) by hub.freebsd.org (Postfix) with ESMTP id 0C94816A41C for ; Mon, 23 May 2005 09:15:26 +0000 (GMT) (envelope-from nobody@FreeBSD.org) Received: from www.freebsd.org (www.freebsd.org [216.136.204.117]) by mx1.FreeBSD.org (Postfix) with ESMTP id 9DBE043D4C for ; Mon, 23 May 2005 09:15:25 +0000 (GMT) (envelope-from nobody@FreeBSD.org) Received: from www.freebsd.org (localhost [127.0.0.1]) by www.freebsd.org (8.13.1/8.13.1) with ESMTP id j4N9FPi1022402 for ; Mon, 23 May 2005 09:15:25 GMT (envelope-from nobody@www.freebsd.org) Received: (from nobody@localhost) by www.freebsd.org (8.13.1/8.13.1/Submit) id j4N9FPAx022401; Mon, 23 May 2005 09:15:25 GMT (envelope-from nobody) Message-Id: <200505230915.j4N9FPAx022401@www.freebsd.org> Date: Mon, 23 May 2005 09:15:25 GMT From: Rayene Ben Rayana To: freebsd-gnats-submit@FreeBSD.org X-Send-Pr-Version: www-2.3 Cc: Subject: i386/81390: ( usermode ppp ) LCP Negotiation Never Finishes, one of the sides never transmit an ack X-BeenThere: freebsd-i386@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: I386-specific issues for FreeBSD List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Mon, 23 May 2005 09:20:03 -0000 >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: