From owner-freebsd-isdn Thu Nov 18 20: 7:46 1999 Delivered-To: freebsd-isdn@freebsd.org Received: from mail2.netcologne.de (mail2.netcologne.de [194.8.194.103]) by hub.freebsd.org (Postfix) with ESMTP id 23AF1154D4 for ; Thu, 18 Nov 1999 20:07:39 -0800 (PST) (envelope-from van.woerkom@netcologne.de) Received: from oranje.my.domain (dial-lind-69.netcologne.de [195.14.250.69]) by mail2.netcologne.de (8.9.3/8.9.3) with ESMTP id FAA11321; Fri, 19 Nov 1999 05:07:36 +0100 (MET) Received: (from marc@localhost) by oranje.my.domain (8.9.3/8.9.3) id FAA13704; Fri, 19 Nov 1999 05:06:47 +0100 (CET) (envelope-from van.woerkom@netcologne.de) Date: Fri, 19 Nov 1999 05:06:47 +0100 (CET) Message-Id: <199911190406.FAA13704@oranje.my.domain> X-Authentication-Warning: oranje.my.domain: marc set sender to van.woerkom@netcologne.de using -f From: Marc van Woerkom To: freebsd-isdn@freebsd.org Subject: Infinite loop (sppp/lcp) Reply-To: van.woerkom@netcologne.de Sender: owner-freebsd-isdn@FreeBSD.ORG Precedence: bulk X-Loop: FreeBSD.org Dear ISDN people, from last Thursday on I was suddenly no longer able to connect to my ISP via ISDN and the i4b package from a mid October 4.0-current. Dang! This was very strange, because I had not changed the system at all for two weeks. So I first thought about a problem with my hardware or the phone company, NetCologne, which is also my ISP. But they told me that they changed nothing at all. Hmm. So I took a look at the last milestones/drastic changes in src/UPGRADE and wasted the weekend applying combinatorics on the isdnd configuration file and building at least 6 older -current snapshot from CVS (it is a time like that, when I feel deep respect for the complexity of i4b and what a mirrored FreeBSD CVS repository is worth) Because I badly needed the Internet access back, I decided to fix this, despite lack of knowledge in that field. The sppp stuff featured in the i4b FAQ, the sppp man page and the sources to sppp are not comprehendable without having read the ppp RFC 1661. It was my luck that I had it on some ancient Linux CD-ROM. I was able to understand that output from ifconfig isp0 debug tcpdump -i isp0 isdntrace to a large degree now. And found that I got stuck in loop at the sppp layer, in the lcp phase. Nov 19 03:09:42 oranje /kernel: isp0: lcp input(ack-sent): Nov 19 03:09:42 oranje /kernel: isp0: lcp parse opts: auth-proto magic lcp/0x11 lcp/0x13 Nov 19 03:09:42 oranje /kernel: isp0: lcp parse opt values: auth-proto magic 0xfcca1cce lcp/0x11 [NetCologne: ignore 0x11] lcp/0x13 [NetCologne: ignore 0x13] send conf-ack Nov 19 03:09:42 oranje /kernel: isp0: lcp output Nov 19 03:09:44 oranje /kernel: isp0: lcp input(ack-sent): Nov 19 03:09:44 oranje /kernel: isp0: lcp parse opts: auth-proto magic lcp/0x11 lcp/0x13 Nov 19 03:09:44 oranje /kernel: isp0: lcp parse opt values: auth-proto magic 0xfcca1cce lcp/0x11 [NetCologne: ignore 0x11] lcp/0x13 [NetCologne: ignore 0x13] send conf-ack Nov 19 03:09:44 oranje /kernel: isp0: lcp output Shortly after I recognized this, I got the idea to weed to the old messages from this mailing list I had on my system and indeed found a couple of mails describing the same problem. Especially the one from another NetCologne user was helpful, because it assured me that it was not my hardware. I called him later (hi! :) and he gave me the tip to use an older i4b version (0.71). Via CVS I was able to see what i4b version was integerated when in -current. However 0.71 corresponds to a -current version that I deemed to old to be useful. So I had no other choice than to hack the sppp driver. This finally let's me write this to you folks at an insane time.. but I am happy it works now again. My solution for all fellow sufferers is the patch below. The reasoning behind it goes like this: - I assume that the peer:conf-req <-> me:conf-ack infinite loop is caused because a conf-ack from peer is not reaching my sppp layer - This is based on looking at the lcp dump of a successful NetCologne ppp connect, posted here and a look of ppp's finite state automaton defined in RFC 1661: | State | 6 7 8 9 Events| Req-Sent Ack-Rcvd Ack-Sent Opened ------+----------------------------------------- Up | - - - - Down | 1 1 1 tld/1 Open | 6 7 8 9r Close|irc,str/4 irc,str/4 irc,str/4 tld,irc,str/4 | TO+ | scr/6 scr/6 scr/8 - TO- | tlf/3p tlf/3p tlf/3p - | RCR+ | sca/8 sca,tlu/9 sca/8 tld,scr,sca/8 RCR- | scn/6 scn/7 scn/6 tld,scr,scn/6 RCA | irc/7 scr/6x irc,tlu/9 tld,scr/6x RCN |irc,scr/6 scr/6x irc,scr/8 tld,scr/6x | RTR | sta/6 sta/6 sta/6 tld,zrc,sta/5 RTA | 6 6 8 tld,scr/6 | RUC | scj/6 scj/7 scj/8 scj/9 RXJ+ | 6 6 8 9 RXJ- | tlf/3 tlf/3 tlf/3 tld,irc,str/5 | RXR | 6 7 8 ser/9 Imagine the automaton at the peer. He must have gotten my RCA (rcvd conf-ack) while being in state 6 after bombing me with conf-reqs. So he should simply reset his timer (irc) and move on to state 7, waiting for an acceptable conf-req from me (sca), signaling the link is up (tlu) and going into state 9. But it does not. For some reason it does answer every of my conf-acks with the same stupid conf-req. My explanation is that the sppp layer has some distorted input. However, it must be a very deep glitch in i4b, at some lower layer, if I am right because the isdntrace of the B-channel data I did corresponded exactly to the data the sppp driver saw. - These strange messages in the isdnd log: 19.11.1999 03:15:18 DBG sendm_connect_req: ctrl = 0, chan = -1 19.11.1999 03:15:18 DBG decr_free_channels: ctrl 0, now 1 chan free 19.11.1999 03:15:18 CHD 00008 NetCologne dialing out from 2769007 to 9174510 19.11.1999 03:15:18 DBG set_channel_busy: controller [0] channel B1 set to BUSY! -> 19.11.1999 03:15:18 CHD 00008 NetCologne outgoing call proceeding (ctl 0, ch 0) -> 19.11.1999 03:15:19 DBG set_channel_busy: controller [0] channel B1 already busy! 19.11.1999 03:15:19 CHD 00008 NetCologne outgoing call active (ctl 0, ch 0, isp0) Or is it normal that 'B1 already busy' message? Could some glitch here result in some lost or duplicate data frames in the higher i4b levels? So I assumed everything is well, and that I got his ack and he got me ack and simply force a tlu with the patch. Not nice, maybe even stupid, but it put me back into business: Nov 19 03:28:29 oranje /kernel: isp0: lcp input(ack-sent): Nov 19 03:28:29 oranje /kernel: isp0: lcp parse opts: auth-proto magic lcp/0x11 lcp/0x13 Nov 19 03:28:29 oranje /kernel: isp0: lcp parse opt values: auth-proto magic 0xfcdb4f9d lcp/0x11 [NetCologne: ignore 0x11] lcp/0x13 [NetCologne: ignore 0x13] send conf-ack Nov 19 03:28:29 oranje /kernel: isp0: lcp output Nov 19 03:28:29 oranje /kernel: fall through NC> Nov 19 03:28:29 oranje /kernel: Nov 19 03:28:29 oranje /kernel: {opened} Nov 19 03:28:29 oranje /kernel: isp0: lcp tlu Nov 19 03:28:29 oranje /kernel: isp0: phase authenticate .. Nov 19 03:28:31 oranje /kernel: isp0: pap success Nov 19 03:28:31 oranje /kernel: isp0: phase network Nov 19 03:28:31 oranje /kernel: isp0: ipcp open(initial) Gotcha! :-) Good night, Marc I am referring to: $FreeBSD: src/sys/net/if_spppsubr.c,v 1.57 1999/10/29 17:57:42 joerg Exp $ --- if_spppsubr.c.orig Wed Nov 17 01:45:26 1999 +++ if_spppsubr.c Fri Nov 19 03:20:44 1999 @@ -1296,7 +1296,6 @@ (cp->tld)(sp); (cp->scr)(sp); /* fall through... */ - case STATE_ACK_SENT: case STATE_REQ_SENT: sppp_cp_change_state(cp, sp, rv? STATE_ACK_SENT: STATE_REQ_SENT); @@ -1307,6 +1306,9 @@ sppp_cp_change_state(cp, sp, rv? STATE_ACK_SENT: STATE_REQ_SENT); break; + case STATE_ACK_SENT: + printf("\n"); + case STATE_ACK_RCVD: if (rv) { sppp_cp_change_state(cp, sp, STATE_OPENED); @@ -1787,6 +1789,9 @@ { sp->state[cp->protoidx] = newstate; + printf("\n{%s}\n", + sppp_state_name(sp->state[cp->protoidx])); + UNTIMEOUT(cp->TO, (void *)sp, sp->ch[cp->protoidx]); switch (newstate) { case STATE_INITIAL: @@ -1989,6 +1994,12 @@ */ sp->pp_flags |= PP_NEEDAUTH; continue; + + /* Hack MvW */ + case 0x11: + case 0x13: + continue; + default: /* Others not supported. */ if (debug) @@ -2102,6 +2113,15 @@ p[4] = CHAP_MD5; break; } + continue; + case 0x11: + if (debug) + addlog("[NetCologne: ignore 0x11] "); + continue; + + case 0x13: + if (debug) + addlog("[NetCologne: ignore 0x13] "); continue; } /* Add the option to nak'ed list. */ To Unsubscribe: send mail to majordomo@FreeBSD.org with "unsubscribe freebsd-isdn" in the body of the message