Date: Wed, 27 Nov 2002 00:11:39 +0700 (KRAT) From: Eugene Grosbein <eugen@grosbein.pp.ru> To: FreeBSD-gnats-submit@FreeBSD.org Subject: bin/45760: pppd(8) incoreectly handles timeouts after long run Message-ID: <200211261711.gAQHBd9D002537@grosbein.pp.ru>
next in thread | raw e-mail | index | archive | help
>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 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoRep id=0x2 magic=0x5dd706b6] Nov 26 22:52:27 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoReq id=0x3 magic=0x5dd706b6] Nov 26 22:52:32 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoReq id=0x4 magic=0x5dd706b6] Nov 26 22:52:37 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoReq id=0x5 magic=0x5dd706b6] Nov 26 22:52:42 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoReq id=0x6 magic=0x5dd706b6] Nov 26 22:52:47 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoReq id=0x7 magic=0x5dd706b6] Nov 26 22:52:52 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoReq id=0x8 magic=0x5dd706b6] Nov 26 22:52:57 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoReq id=0x9 magic=0x5dd706b6] Nov 26 22:53:02 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoReq id=0xa magic=0x5dd706b6] Nov 26 22:53:07 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoReq id=0xb magic=0x5dd706b6] Nov 26 22:53:13 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoReq id=0xc magic=0x5dd706b6] Nov 26 22:53:18 <daemon.info> grosbein pppd[1147]: No response to 10 echo-requests It reconnects but shortens interval for unknown reason: Nov 26 22:53:18 <daemon.notice> grosbein pppd[1147]: Serial link appears to be disconnected. Nov 26 22:53:18 <daemon.debug> grosbein pppd[1147]: sent [LCP TermReq id=0x2 "Peer not responding"] Nov 26 22:53:21 <daemon.debug> grosbein pppd[1147]: sent [LCP TermReq id=0x3 "Peer not responding"] Nov 26 22:53:24 <daemon.notice> grosbein pppd[1147]: Connection terminated, connected for 1 minutes Nov 26 22:53:34 <daemon.warn> grosbein pppd[1147]: disconnect script failed Nov 26 22:56:02 <daemon.info> grosbein pppd[1147]: Serial connection established. Nov 26 22:56:03 <daemon.info> grosbein pppd[1147]: Using interface ppp0 Nov 26 22:56:03 <daemon.notice> grosbein pppd[1147]: Connect: ppp0 <--> /dev/cuaa1 Nov 26 22:56:03 <daemon.debug> grosbein pppd[1147]: sent [LCP ConfReq id=0x4 <mru 576> <asyncmap 0x0> <magic 0x3ec3353> <pcomp> <accomp>] Nov 26 22:56:03 <daemon.debug> grosbein pppd[1147]: rcvd [LCP ConfAck id=0x4 <mru 576> <asyncmap 0x0> <magic 0x3ec3353> <pcomp> <accomp>] Nov 26 22:56:05 <daemon.debug> grosbein pppd[1147]: rcvd [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x8f999505> <pcomp> <accomp>] Nov 26 22:56:05 <daemon.debug> grosbein pppd[1147]: sent [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0x8f999505> <pcomp> <accomp>] Nov 26 22:56:05 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoReq id=0x0 magic=0x3ec3353] Nov 26 22:56:05 <daemon.debug> grosbein pppd[1147]: sent [IPCP ConfReq id=0x3 <addr 0.0.0.0> <compress VJ 0f 01>] Nov 26 22:56:05 <daemon.debug> grosbein pppd[1147]: sent [CCP ConfReq id=0x2 <deflate 15> <deflate(old#) 15> <bsd v1 15>] Nov 26 22:56:05 <daemon.debug> grosbein pppd[1147]: rcvd [LCP EchoReq id=0x0 magic=0x8f999505] Nov 26 22:56:05 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoRep id=0x0 magic=0x3ec3353] Nov 26 22:56:05 <daemon.debug> grosbein pppd[1147]: rcvd [IPCP ConfReq id=0x1 <addr 213.184.65.80> <compress VJ 0f 01>] Nov 26 22:56:05 <daemon.debug> grosbein pppd[1147]: sent [IPCP ConfAck id=0x1 <addr 213.184.65.80> <compress VJ 0f 01>] Nov 26 22:56:05 <daemon.debug> grosbein pppd[1147]: rcvd [CCP ConfReq id=0x1 <deflate 15> <deflate(old#) 15> <bsd v1 15>] Nov 26 22:56:05 <daemon.debug> grosbein pppd[1147]: sent [CCP ConfAck id=0x1 <deflate 15> <deflate(old#) 15> <bsd v1 15>] Nov 26 22:56:05 <daemon.debug> grosbein pppd[1147]: rcvd [LCP EchoRep id=0x0 magic=0x8f999505] Nov 26 22:56:05 <daemon.debug> grosbein pppd[1147]: rcvd [IPCP ConfNak id=0x3 <addr 213.184.65.86>] Nov 26 22:56:05 <daemon.debug> grosbein pppd[1147]: sent [IPCP ConfReq id=0x4 <addr 213.184.65.86> <compress VJ 0f 01>] Nov 26 22:56:05 <daemon.debug> grosbein pppd[1147]: rcvd [CCP ConfAck id=0x2 <deflate 15> <deflate(old#) 15> <bsd v1 15>] Nov 26 22:56:05 <daemon.notice> grosbein pppd[1147]: Deflate (15) compression enabled Nov 26 22:56:05 <daemon.debug> grosbein pppd[1147]: rcvd [IPCP ConfAck id=0x4 <addr 213.184.65.86> <compress VJ 0f 01>] Nov 26 22:56:05 <daemon.notice> grosbein pppd[1147]: local IP address 213.184.65.86 Nov 26 22:56:05 <daemon.notice> grosbein pppd[1147]: remote IP address 213.184.65.80 Now it sends echos every 2-3 seconds: Nov 26 22:56:08 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoReq id=0x1 magic=0x3ec3353] Nov 26 22:56:08 <daemon.debug> grosbein pppd[1147]: rcvd [LCP EchoRep id=0x1 magic=0x8f999505] Nov 26 22:56:10 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoReq id=0x2 magic=0x3ec3353] Nov 26 22:56:10 <daemon.debug> grosbein pppd[1147]: rcvd [LCP EchoRep id=0x2 magic=0x8f999505] Nov 26 22:56:11 <daemon.debug> grosbein pppd[1147]: rcvd [LCP EchoReq id=0x1 magic=0x8f999505] Nov 26 22:56:11 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoRep id=0x1 magic=0x3ec3353] Nov 26 22:56:13 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoReq id=0x3 magic=0x3ec3353] Nov 26 22:56:13 <daemon.debug> grosbein pppd[1147]: rcvd [LCP EchoRep id=0x3 magic=0x8f999505] Nov 26 22:56:15 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoReq id=0x4 magic=0x3ec3353] Nov 26 22:56:15 <daemon.debug> grosbein pppd[1147]: rcvd [LCP EchoRep id=0x4 magic=0x8f999505] Nov 26 22:56:17 <daemon.debug> grosbein pppd[1147]: rcvd [LCP EchoReq id=0x2 magic=0x8f999505] Nov 26 22:56:17 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoRep id=0x2 magic=0x3ec3353] Nov 26 22:56:18 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoReq id=0x5 magic=0x3ec3353] Nov 26 22:56:18 <daemon.debug> grosbein pppd[1147]: rcvd [LCP EchoRep id=0x5 magic=0x8f999505] Nov 26 22:56:20 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoReq id=0x6 magic=0x3ec3353] Nov 26 22:56:21 <daemon.debug> grosbein pppd[1147]: rcvd [LCP EchoRep id=0x6 magic=0x8f999505] Nov 26 22:56:23 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoReq id=0x7 magic=0x3ec3353] Nov 26 22:56:23 <daemon.debug> grosbein pppd[1147]: rcvd [LCP EchoRep id=0x7 magic=0x8f999505] Nov 26 22:56:23 <daemon.debug> grosbein pppd[1147]: rcvd [LCP EchoReq id=0x3 magic=0x8f999505] Nov 26 22:56:23 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoRep id=0x3 magic=0x3ec3353] Nov 26 22:56:25 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoReq id=0x8 magic=0x3ec3353] Nov 26 22:56:25 <daemon.debug> grosbein pppd[1147]: rcvd [LCP EchoRep id=0x8 magic=0x8f999505] Nov 26 22:56:28 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoReq id=0x9 magic=0x3ec3353] Nov 26 22:56:29 <daemon.debug> grosbein pppd[1147]: rcvd [LCP EchoReq id=0x4 magic=0x8f999505] Nov 26 22:56:29 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoRep id=0x4 magic=0x3ec3353] Nov 26 22:56:30 <daemon.debug> grosbein pppd[1147]: rcvd [LCP EchoRep id=0x9 magic=0x8f999505] [skip] Eventually link hangs, it reconnects again. Nov 26 23:00:06 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoRep id=0x28 magic=0x3ec3353] Nov 26 23:00:08 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoReq id=0x61 magic=0x3ec3353] Nov 26 23:00:11 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoReq id=0x62 magic=0x3ec3353] Nov 26 23:00:13 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoReq id=0x63 magic=0x3ec3353] Nov 26 23:00:16 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoReq id=0x64 magic=0x3ec3353] Nov 26 23:00:18 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoReq id=0x65 magic=0x3ec3353] Nov 26 23:00:21 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoReq id=0x66 magic=0x3ec3353] Nov 26 23:00:23 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoReq id=0x67 magic=0x3ec3353] Nov 26 23:00:26 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoReq id=0x68 magic=0x3ec3353] Nov 26 23:00:28 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoReq id=0x69 magic=0x3ec3353] Nov 26 23:00:31 <daemon.info> grosbein pppd[1147]: No response to 10 echo-requests Nov 26 23:00:31 <daemon.notice> 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 <daemon.debug> grosbein pppd[1147]: sent [LCP TermReq id=0x5 "Peer not responding"] Nov 26 23:00:34 <daemon.debug> grosbein pppd[1147]: sent [LCP TermReq id=0x6 "Peer not responding"] Nov 26 23:00:37 <daemon.notice> grosbein pppd[1147]: Connection terminated, connected for 4 minutes Nov 26 23:00:39 <daemon.info> grosbein pppd[1147]: Serial link disconnected. Nov 26 23:02:09 <daemon.info> grosbein pppd[1147]: Serial connection established. Nov 26 23:02:10 <daemon.info> grosbein pppd[1147]: Using interface ppp0 Nov 26 23:02:10 <daemon.notice> grosbein pppd[1147]: Connect: ppp0 <--> /dev/cuaa1 Nov 26 23:02:10 <daemon.debug> grosbein pppd[1147]: sent [LCP ConfReq id=0x7 <mru 576> <asyncmap 0x0> <magic 0x7428887f> <pcomp> <accomp>] Nov 26 23:02:10 <daemon.debug> grosbein pppd[1147]: rcvd [LCP ConfAck id=0x7 <mru 576> <asyncmap 0x0> <magic 0x7428887f> <pcomp> <accomp>] Nov 26 23:02:12 <daemon.debug> grosbein pppd[1147]: rcvd [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0xee8636e5> <pcomp> <accomp>] Nov 26 23:02:12 <daemon.debug> grosbein pppd[1147]: sent [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0xee8636e5> <pcomp> <accomp>] Nov 26 23:02:12 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoReq id=0x0 magic=0x7428887f] Nov 26 23:02:12 <daemon.debug> grosbein pppd[1147]: sent [IPCP ConfReq id=0x5 <addr 0.0.0.0> <compress VJ 0f 01>] Nov 26 23:02:12 <daemon.debug> grosbein pppd[1147]: sent [CCP ConfReq id=0x3 <deflate 15> <deflate(old#) 15> <bsd v1 15>] Nov 26 23:02:12 <daemon.debug> grosbein pppd[1147]: rcvd [LCP EchoReq id=0x0 magic=0xee8636e5] Nov 26 23:02:12 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoRep id=0x0 magic=0x7428887f] Nov 26 23:02:12 <daemon.debug> grosbein pppd[1147]: rcvd [IPCP ConfReq id=0x1 <addr 213.184.65.80> <compress VJ 0f 01>] Nov 26 23:02:12 <daemon.debug> grosbein pppd[1147]: sent [IPCP ConfAck id=0x1 <addr 213.184.65.80> <compress VJ 0f 01>] Nov 26 23:02:12 <daemon.debug> grosbein pppd[1147]: rcvd [CCP ConfReq id=0x1 <deflate 15> <deflate(old#) 15> <bsd v1 15>] Nov 26 23:02:12 <daemon.debug> grosbein pppd[1147]: sent [CCP ConfAck id=0x1 <deflate 15> <deflate(old#) 15> <bsd v1 15>] Nov 26 23:02:12 <daemon.debug> grosbein pppd[1147]: rcvd [IPCP ConfNak id=0x5 <addr 213.184.65.86>] Nov 26 23:02:12 <daemon.debug> grosbein pppd[1147]: sent [IPCP ConfReq id=0x6 <addr 213.184.65.86> <compress VJ 0f 01>] Nov 26 23:02:12 <daemon.debug> grosbein pppd[1147]: rcvd [CCP ConfAck id=0x3 <deflate 15> <deflate(old#) 15> <bsd v1 15>] Nov 26 23:02:12 <daemon.notice> grosbein pppd[1147]: Deflate (15) compression enabled Nov 26 23:02:12 <daemon.debug> grosbein pppd[1147]: rcvd [IPCP ConfAck id=0x6 <addr 213.184.65.86> <compress VJ 0f 01>] Nov 26 23:02:12 <daemon.notice> grosbein pppd[1147]: local IP address 213.184.65.86 Nov 26 23:02:12 <daemon.notice> grosbein pppd[1147]: remote IP address 213.184.65.80 It sends echos upto two per second: Nov 26 23:02:15 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoReq id=0x1 magic=0x7428887f] Nov 26 23:02:15 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoReq id=0x2 magic=0x7428887f] Nov 26 23:02:15 <daemon.debug> grosbein pppd[1147]: rcvd [LCP EchoRep id=0x1 magic=0xee8636e5] Nov 26 23:02:15 <daemon.debug> grosbein pppd[1147]: rcvd [LCP EchoRep id=0x2 magic=0xee8636e5] Nov 26 23:02:17 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoReq id=0x3 magic=0x7428887f] Nov 26 23:02:20 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoReq id=0x4 magic=0x7428887f] Nov 26 23:02:20 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoReq id=0x5 magic=0x7428887f] Nov 26 23:02:22 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoReq id=0x6 magic=0x7428887f] Nov 26 23:02:25 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoReq id=0x7 magic=0x7428887f] Nov 26 23:02:25 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoReq id=0x8 magic=0x7428887f] Nov 26 23:02:27 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoReq id=0x9 magic=0x7428887f] Nov 26 23:02:30 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoReq id=0xa magic=0x7428887f] Nov 26 23:02:30 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoReq id=0xb magic=0x7428887f] Nov 26 23:02:32 <daemon.debug> grosbein pppd[1147]: sent [LCP EchoReq id=0xc magic=0x7428887f] Nov 26 23:02:35 <daemon.info> grosbein pppd[1147]: No response to 10 echo-requests Nov 26 23:02:35 <daemon.notice> grosbein pppd[1147]: Serial link appears to be disconnected. Nov 26 23:02:35 <daemon.debug> grosbein pppd[1147]: sent [LCP TermReq id=0x8 "Peer not responding"] Nov 26 23:02:38 <daemon.debug> grosbein pppd[1147]: sent [LCP TermReq id=0x9 "Peer not responding"] Nov 26 23:02:41 <daemon.notice> grosbein pppd[1147]: Connection terminated, connected for 1 minutes Nov 26 23:02:41 <daemon.info> 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
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?200211261711.gAQHBd9D002537>