From owner-freebsd-bugs Tue Nov 26 9:20: 9 2002 Delivered-To: freebsd-bugs@hub.freebsd.org Received: from mx1.FreeBSD.org (mx1.freebsd.org [216.136.204.125]) by hub.freebsd.org (Postfix) with ESMTP id 384FB37B401 for ; Tue, 26 Nov 2002 09:20:03 -0800 (PST) Received: from freefall.freebsd.org (freefall.freebsd.org [216.136.204.21]) by mx1.FreeBSD.org (Postfix) with ESMTP id 7CF8E43EB2 for ; Tue, 26 Nov 2002 09:20:01 -0800 (PST) (envelope-from gnats@FreeBSD.org) Received: from freefall.freebsd.org (gnats@localhost [127.0.0.1]) by freefall.freebsd.org (8.12.6/8.12.6) with ESMTP id gAQHK1x3031865 for ; Tue, 26 Nov 2002 09:20:01 -0800 (PST) (envelope-from gnats@freefall.freebsd.org) Received: (from gnats@localhost) by freefall.freebsd.org (8.12.6/8.12.6/Submit) id gAQHK1ge031864; Tue, 26 Nov 2002 09:20:01 -0800 (PST) Received: from mx1.FreeBSD.org (mx1.freebsd.org [216.136.204.125]) by hub.freebsd.org (Postfix) with ESMTP id A3B8237B401 for ; Tue, 26 Nov 2002 09:12:09 -0800 (PST) Received: from grosbein.pp.ru (www2.svzserv.kemerovo.su [213.184.65.86]) by mx1.FreeBSD.org (Postfix) with ESMTP id EB48B43E9C for ; Tue, 26 Nov 2002 09:11:59 -0800 (PST) (envelope-from eugen@grosbein.pp.ru) Received: from grosbein.pp.ru (smmsp@localhost [127.0.0.1]) by grosbein.pp.ru (8.12.6/8.12.5) with ESMTP id gAQHBngD002541 for ; Wed, 27 Nov 2002 00:11:49 +0700 (KRAT) (envelope-from eugen@grosbein.pp.ru) Received: (from eugen@localhost) by grosbein.pp.ru (8.12.6/8.12.6/Submit) id gAQHBd9D002537; Wed, 27 Nov 2002 00:11:39 +0700 (KRAT) Message-Id: <200211261711.gAQHBd9D002537@grosbein.pp.ru> Date: Wed, 27 Nov 2002 00:11:39 +0700 (KRAT) From: Eugene Grosbein Reply-To: Eugene Grosbein To: FreeBSD-gnats-submit@FreeBSD.org X-Send-Pr-Version: 3.113 Subject: bin/45760: pppd(8) incoreectly handles timeouts after long run Sender: owner-freebsd-bugs@FreeBSD.ORG Precedence: bulk List-ID: List-Archive: (Web Archive) List-Help: (List Instructions) List-Subscribe: List-Unsubscribe: X-Loop: FreeBSD.org >Number: 45760 >Category: bin >Synopsis: pppd(8) incoreectly handles timeouts after long run >Confidential: no >Severity: serious >Priority: low >Responsible: freebsd-bugs >State: open >Quarter: >Keywords: >Date-Required: >Class: sw-bug >Submitter-Id: current-users >Arrival-Date: Tue Nov 26 09:20:00 PST 2002 >Closed-Date: >Last-Modified: >Originator: Eugene Grosbein >Release: FreeBSD 4.7-STABLE i386 >Organization: Svyaz Service JSC >Environment: System: FreeBSD grosbein.pp.ru 4.7-STABLE FreeBSD 4.7-STABLE #22: Sun Oct 13 14:25:47 KRAST 2002 eu@grosbein.pp.ru:/usr/local/obj/usr/local/src/sys/DADV i386 Stock pppd >Description: While running pppd(8) over dialup lines one sometimes have to use LCP Echo to detect not responding peer. It was remarked that pppd(8) sometimes fails to handle lcp timeouts after long run. >How-To-Repeat: I cannot always reproduce this but this happens annoying often. This happens when pppd runs with options: lcp-echo-interval 5 lcp-echo-failure 10 persist Here is a typical scenario, real log. First it sends LCP echos correctly: Nov 26 22:52:23 grosbein pppd[1147]: sent [LCP EchoRep id=0x2 magic=0x5dd706b6] Nov 26 22:52:27 grosbein pppd[1147]: sent [LCP EchoReq id=0x3 magic=0x5dd706b6] Nov 26 22:52:32 grosbein pppd[1147]: sent [LCP EchoReq id=0x4 magic=0x5dd706b6] Nov 26 22:52:37 grosbein pppd[1147]: sent [LCP EchoReq id=0x5 magic=0x5dd706b6] Nov 26 22:52:42 grosbein pppd[1147]: sent [LCP EchoReq id=0x6 magic=0x5dd706b6] Nov 26 22:52:47 grosbein pppd[1147]: sent [LCP EchoReq id=0x7 magic=0x5dd706b6] Nov 26 22:52:52 grosbein pppd[1147]: sent [LCP EchoReq id=0x8 magic=0x5dd706b6] Nov 26 22:52:57 grosbein pppd[1147]: sent [LCP EchoReq id=0x9 magic=0x5dd706b6] Nov 26 22:53:02 grosbein pppd[1147]: sent [LCP EchoReq id=0xa magic=0x5dd706b6] Nov 26 22:53:07 grosbein pppd[1147]: sent [LCP EchoReq id=0xb magic=0x5dd706b6] Nov 26 22:53:13 grosbein pppd[1147]: sent [LCP EchoReq id=0xc magic=0x5dd706b6] Nov 26 22:53:18 grosbein pppd[1147]: No response to 10 echo-requests It reconnects but shortens interval for unknown reason: Nov 26 22:53:18 grosbein pppd[1147]: Serial link appears to be disconnected. Nov 26 22:53:18 grosbein pppd[1147]: sent [LCP TermReq id=0x2 "Peer not responding"] Nov 26 22:53:21 grosbein pppd[1147]: sent [LCP TermReq id=0x3 "Peer not responding"] Nov 26 22:53:24 grosbein pppd[1147]: Connection terminated, connected for 1 minutes Nov 26 22:53:34 grosbein pppd[1147]: disconnect script failed Nov 26 22:56:02 grosbein pppd[1147]: Serial connection established. Nov 26 22:56:03 grosbein pppd[1147]: Using interface ppp0 Nov 26 22:56:03 grosbein pppd[1147]: Connect: ppp0 <--> /dev/cuaa1 Nov 26 22:56:03 grosbein pppd[1147]: sent [LCP ConfReq id=0x4 ] Nov 26 22:56:03 grosbein pppd[1147]: rcvd [LCP ConfAck id=0x4 ] Nov 26 22:56:05 grosbein pppd[1147]: rcvd [LCP ConfReq id=0x1 ] Nov 26 22:56:05 grosbein pppd[1147]: sent [LCP ConfAck id=0x1 ] Nov 26 22:56:05 grosbein pppd[1147]: sent [LCP EchoReq id=0x0 magic=0x3ec3353] Nov 26 22:56:05 grosbein pppd[1147]: sent [IPCP ConfReq id=0x3 ] Nov 26 22:56:05 grosbein pppd[1147]: sent [CCP ConfReq id=0x2 ] Nov 26 22:56:05 grosbein pppd[1147]: rcvd [LCP EchoReq id=0x0 magic=0x8f999505] Nov 26 22:56:05 grosbein pppd[1147]: sent [LCP EchoRep id=0x0 magic=0x3ec3353] Nov 26 22:56:05 grosbein pppd[1147]: rcvd [IPCP ConfReq id=0x1 ] Nov 26 22:56:05 grosbein pppd[1147]: sent [IPCP ConfAck id=0x1 ] Nov 26 22:56:05 grosbein pppd[1147]: rcvd [CCP ConfReq id=0x1 ] Nov 26 22:56:05 grosbein pppd[1147]: sent [CCP ConfAck id=0x1 ] Nov 26 22:56:05 grosbein pppd[1147]: rcvd [LCP EchoRep id=0x0 magic=0x8f999505] Nov 26 22:56:05 grosbein pppd[1147]: rcvd [IPCP ConfNak id=0x3 ] Nov 26 22:56:05 grosbein pppd[1147]: sent [IPCP ConfReq id=0x4 ] Nov 26 22:56:05 grosbein pppd[1147]: rcvd [CCP ConfAck id=0x2 ] Nov 26 22:56:05 grosbein pppd[1147]: Deflate (15) compression enabled Nov 26 22:56:05 grosbein pppd[1147]: rcvd [IPCP ConfAck id=0x4 ] Nov 26 22:56:05 grosbein pppd[1147]: local IP address 213.184.65.86 Nov 26 22:56:05 grosbein pppd[1147]: remote IP address 213.184.65.80 Now it sends echos every 2-3 seconds: Nov 26 22:56:08 grosbein pppd[1147]: sent [LCP EchoReq id=0x1 magic=0x3ec3353] Nov 26 22:56:08 grosbein pppd[1147]: rcvd [LCP EchoRep id=0x1 magic=0x8f999505] Nov 26 22:56:10 grosbein pppd[1147]: sent [LCP EchoReq id=0x2 magic=0x3ec3353] Nov 26 22:56:10 grosbein pppd[1147]: rcvd [LCP EchoRep id=0x2 magic=0x8f999505] Nov 26 22:56:11 grosbein pppd[1147]: rcvd [LCP EchoReq id=0x1 magic=0x8f999505] Nov 26 22:56:11 grosbein pppd[1147]: sent [LCP EchoRep id=0x1 magic=0x3ec3353] Nov 26 22:56:13 grosbein pppd[1147]: sent [LCP EchoReq id=0x3 magic=0x3ec3353] Nov 26 22:56:13 grosbein pppd[1147]: rcvd [LCP EchoRep id=0x3 magic=0x8f999505] Nov 26 22:56:15 grosbein pppd[1147]: sent [LCP EchoReq id=0x4 magic=0x3ec3353] Nov 26 22:56:15 grosbein pppd[1147]: rcvd [LCP EchoRep id=0x4 magic=0x8f999505] Nov 26 22:56:17 grosbein pppd[1147]: rcvd [LCP EchoReq id=0x2 magic=0x8f999505] Nov 26 22:56:17 grosbein pppd[1147]: sent [LCP EchoRep id=0x2 magic=0x3ec3353] Nov 26 22:56:18 grosbein pppd[1147]: sent [LCP EchoReq id=0x5 magic=0x3ec3353] Nov 26 22:56:18 grosbein pppd[1147]: rcvd [LCP EchoRep id=0x5 magic=0x8f999505] Nov 26 22:56:20 grosbein pppd[1147]: sent [LCP EchoReq id=0x6 magic=0x3ec3353] Nov 26 22:56:21 grosbein pppd[1147]: rcvd [LCP EchoRep id=0x6 magic=0x8f999505] Nov 26 22:56:23 grosbein pppd[1147]: sent [LCP EchoReq id=0x7 magic=0x3ec3353] Nov 26 22:56:23 grosbein pppd[1147]: rcvd [LCP EchoRep id=0x7 magic=0x8f999505] Nov 26 22:56:23 grosbein pppd[1147]: rcvd [LCP EchoReq id=0x3 magic=0x8f999505] Nov 26 22:56:23 grosbein pppd[1147]: sent [LCP EchoRep id=0x3 magic=0x3ec3353] Nov 26 22:56:25 grosbein pppd[1147]: sent [LCP EchoReq id=0x8 magic=0x3ec3353] Nov 26 22:56:25 grosbein pppd[1147]: rcvd [LCP EchoRep id=0x8 magic=0x8f999505] Nov 26 22:56:28 grosbein pppd[1147]: sent [LCP EchoReq id=0x9 magic=0x3ec3353] Nov 26 22:56:29 grosbein pppd[1147]: rcvd [LCP EchoReq id=0x4 magic=0x8f999505] Nov 26 22:56:29 grosbein pppd[1147]: sent [LCP EchoRep id=0x4 magic=0x3ec3353] Nov 26 22:56:30 grosbein pppd[1147]: rcvd [LCP EchoRep id=0x9 magic=0x8f999505] [skip] Eventually link hangs, it reconnects again. Nov 26 23:00:06 grosbein pppd[1147]: sent [LCP EchoRep id=0x28 magic=0x3ec3353] Nov 26 23:00:08 grosbein pppd[1147]: sent [LCP EchoReq id=0x61 magic=0x3ec3353] Nov 26 23:00:11 grosbein pppd[1147]: sent [LCP EchoReq id=0x62 magic=0x3ec3353] Nov 26 23:00:13 grosbein pppd[1147]: sent [LCP EchoReq id=0x63 magic=0x3ec3353] Nov 26 23:00:16 grosbein pppd[1147]: sent [LCP EchoReq id=0x64 magic=0x3ec3353] Nov 26 23:00:18 grosbein pppd[1147]: sent [LCP EchoReq id=0x65 magic=0x3ec3353] Nov 26 23:00:21 grosbein pppd[1147]: sent [LCP EchoReq id=0x66 magic=0x3ec3353] Nov 26 23:00:23 grosbein pppd[1147]: sent [LCP EchoReq id=0x67 magic=0x3ec3353] Nov 26 23:00:26 grosbein pppd[1147]: sent [LCP EchoReq id=0x68 magic=0x3ec3353] Nov 26 23:00:28 grosbein pppd[1147]: sent [LCP EchoReq id=0x69 magic=0x3ec3353] Nov 26 23:00:31 grosbein pppd[1147]: No response to 10 echo-requests Nov 26 23:00:31 grosbein pppd[1147]: Serial link appears to be disconnected. But now it sends echos very quickly and falsely decides that link is disconnected: Nov 26 23:00:31 grosbein pppd[1147]: sent [LCP TermReq id=0x5 "Peer not responding"] Nov 26 23:00:34 grosbein pppd[1147]: sent [LCP TermReq id=0x6 "Peer not responding"] Nov 26 23:00:37 grosbein pppd[1147]: Connection terminated, connected for 4 minutes Nov 26 23:00:39 grosbein pppd[1147]: Serial link disconnected. Nov 26 23:02:09 grosbein pppd[1147]: Serial connection established. Nov 26 23:02:10 grosbein pppd[1147]: Using interface ppp0 Nov 26 23:02:10 grosbein pppd[1147]: Connect: ppp0 <--> /dev/cuaa1 Nov 26 23:02:10 grosbein pppd[1147]: sent [LCP ConfReq id=0x7 ] Nov 26 23:02:10 grosbein pppd[1147]: rcvd [LCP ConfAck id=0x7 ] Nov 26 23:02:12 grosbein pppd[1147]: rcvd [LCP ConfReq id=0x1 ] Nov 26 23:02:12 grosbein pppd[1147]: sent [LCP ConfAck id=0x1 ] Nov 26 23:02:12 grosbein pppd[1147]: sent [LCP EchoReq id=0x0 magic=0x7428887f] Nov 26 23:02:12 grosbein pppd[1147]: sent [IPCP ConfReq id=0x5 ] Nov 26 23:02:12 grosbein pppd[1147]: sent [CCP ConfReq id=0x3 ] Nov 26 23:02:12 grosbein pppd[1147]: rcvd [LCP EchoReq id=0x0 magic=0xee8636e5] Nov 26 23:02:12 grosbein pppd[1147]: sent [LCP EchoRep id=0x0 magic=0x7428887f] Nov 26 23:02:12 grosbein pppd[1147]: rcvd [IPCP ConfReq id=0x1 ] Nov 26 23:02:12 grosbein pppd[1147]: sent [IPCP ConfAck id=0x1 ] Nov 26 23:02:12 grosbein pppd[1147]: rcvd [CCP ConfReq id=0x1 ] Nov 26 23:02:12 grosbein pppd[1147]: sent [CCP ConfAck id=0x1 ] Nov 26 23:02:12 grosbein pppd[1147]: rcvd [IPCP ConfNak id=0x5 ] Nov 26 23:02:12 grosbein pppd[1147]: sent [IPCP ConfReq id=0x6 ] Nov 26 23:02:12 grosbein pppd[1147]: rcvd [CCP ConfAck id=0x3 ] Nov 26 23:02:12 grosbein pppd[1147]: Deflate (15) compression enabled Nov 26 23:02:12 grosbein pppd[1147]: rcvd [IPCP ConfAck id=0x6 ] Nov 26 23:02:12 grosbein pppd[1147]: local IP address 213.184.65.86 Nov 26 23:02:12 grosbein pppd[1147]: remote IP address 213.184.65.80 It sends echos upto two per second: Nov 26 23:02:15 grosbein pppd[1147]: sent [LCP EchoReq id=0x1 magic=0x7428887f] Nov 26 23:02:15 grosbein pppd[1147]: sent [LCP EchoReq id=0x2 magic=0x7428887f] Nov 26 23:02:15 grosbein pppd[1147]: rcvd [LCP EchoRep id=0x1 magic=0xee8636e5] Nov 26 23:02:15 grosbein pppd[1147]: rcvd [LCP EchoRep id=0x2 magic=0xee8636e5] Nov 26 23:02:17 grosbein pppd[1147]: sent [LCP EchoReq id=0x3 magic=0x7428887f] Nov 26 23:02:20 grosbein pppd[1147]: sent [LCP EchoReq id=0x4 magic=0x7428887f] Nov 26 23:02:20 grosbein pppd[1147]: sent [LCP EchoReq id=0x5 magic=0x7428887f] Nov 26 23:02:22 grosbein pppd[1147]: sent [LCP EchoReq id=0x6 magic=0x7428887f] Nov 26 23:02:25 grosbein pppd[1147]: sent [LCP EchoReq id=0x7 magic=0x7428887f] Nov 26 23:02:25 grosbein pppd[1147]: sent [LCP EchoReq id=0x8 magic=0x7428887f] Nov 26 23:02:27 grosbein pppd[1147]: sent [LCP EchoReq id=0x9 magic=0x7428887f] Nov 26 23:02:30 grosbein pppd[1147]: sent [LCP EchoReq id=0xa magic=0x7428887f] Nov 26 23:02:30 grosbein pppd[1147]: sent [LCP EchoReq id=0xb magic=0x7428887f] Nov 26 23:02:32 grosbein pppd[1147]: sent [LCP EchoReq id=0xc magic=0x7428887f] Nov 26 23:02:35 grosbein pppd[1147]: No response to 10 echo-requests Nov 26 23:02:35 grosbein pppd[1147]: Serial link appears to be disconnected. Nov 26 23:02:35 grosbein pppd[1147]: sent [LCP TermReq id=0x8 "Peer not responding"] Nov 26 23:02:38 grosbein pppd[1147]: sent [LCP TermReq id=0x9 "Peer not responding"] Nov 26 23:02:41 grosbein pppd[1147]: Connection terminated, connected for 1 minutes Nov 26 23:02:41 grosbein pppd[1147]: Serial link disconnected. Next time it sends upto 4 echos per second. Eventually it starts to send all 10 echos in one second and breaks link immediately after is's established. Now one must kill pppd and restart it manually to restore correct operations. pppd will work Ok just after restart and may work Ok for long time but sometimes it repeats this scenario. >Fix: Unknown to me. >Release-Note: >Audit-Trail: >Unformatted: To Unsubscribe: send mail to majordomo@FreeBSD.org with "unsubscribe freebsd-bugs" in the body of the message