From owner-freebsd-isdn Sat Feb 10 11:45:26 2001 Delivered-To: freebsd-isdn@freebsd.org Received: from liliput.tmp.com.br (liliput.tmp.com.br [200.244.62.12]) by hub.freebsd.org (Postfix) with ESMTP id 3613037B65D for ; Sat, 10 Feb 2001 11:44:53 -0800 (PST) Received: (from prallon@localhost) by liliput.tmp.com.br (8.8.8/8.8.8) id RAA26152; Sat, 10 Feb 2001 17:44:31 -0200 Date: Sat, 10 Feb 2001 17:44:31 -0200 From: Sergio de Souza Prallon To: Igor Prystay Cc: freebsd-isdn@freebsd.org Subject: Re: Teles/PCI card Message-ID: <20010210174431.A26048@tmp.com.br> References: <3A81C486.3A764FA6@inobject.com> <20010207232601.A8398@tmp.com.br> <000901c093d9$4a0c24b0$5100a8c0@iptest> Mime-Version: 1.0 Content-Type: text/plain; charset=us-ascii X-Mailer: Mutt 1.0i In-Reply-To: <000901c093d9$4a0c24b0$5100a8c0@iptest>; from igorp@inobject.com on Sat, Feb 10, 2001 at 07:16:20PM -0800 X-URL: http://www.tmp.com.br Sender: owner-freebsd-isdn@FreeBSD.ORG Precedence: bulk X-Loop: FreeBSD.org On Sat, Feb 10, 2001 at 07:16:20PM -0800, Igor Prystay wrote: > > Hi Sergio ! > Thank You for answer > You're right - it was my provider problems, next day no probems with access > to your site, I compiled the driver without any problem > But now I have a problems with configuration - if this is posible could you > give me some recomendation ? > I spent a lot of time tryeing figured out why it doesn't work but without > success ... Under NT it works fine. > > Igor > I had a look at your trace output and I believe I've found the `nature' of your problems. I am not an expert in L2 or L3 so I'm relaying to the list (freebsd-isdn@freebsd.org -- if you're not subscribed you should consider doing so) in the hope to get a more precise diagnostic. Scroll down to the isdntrace output below. > from my dmesg.log : > > Feb 10 17:30:15 test /kernel: itjc0: port 0xd800-0xd8ff mem > 0xfeaff000-0xfeafffff irq 9 at device 10.0 on pci2 > Feb 10 17:30:15 test /kernel: itjc0: ISAC 2186 Version 1.1 (IOM-2) > Feb 10 17:30:15 test /kernel: itjc0: passive stack unit 0 > Feb 10 17:30:15 test /kernel: rl0: port > 0xd400-0xd4ff mem 0xfeafec00-0xfeafecff irq 9 at device 12.0 on pci2 > Feb 10 17:30:15 test /kernel: rl0: Ethernet address: 00:00:21:03:76:8f > Feb 10 17:30:15 test /kernel: miibus0: on rl0 > Feb 10 17:30:15 test /kernel: rlphy0: on > miibus0 > Feb 10 17:30:15 test /kernel: rlphy0: 10baseT, 10baseT-FDX, 100baseTX, > 100baseTX-FDX, auto > Feb 10 17:30:15 test /kernel: isab0: > at device 31.0 on pci0 > Feb 10 17:30:15 test /kernel: isa0: on isab0 > Feb 10 17:30:15 test /kernel: atapci0: port > 0xffa0-0xffaf at device 31.1 on pci0 > Feb 10 17:30:15 test /kernel: ata0: at 0x1f0 irq 14 on atapci0 > Feb 10 17:30:15 test /kernel: ata1: at 0x170 irq 15 on atapci0 > Feb 10 17:30:15 test /kernel: pci0: at > 31.2 irq 10 > Feb 10 17:30:15 test /kernel: pci0: (vendor=0x8086, > dev=0x2413) at 31.3 irq 11 > Feb 10 17:30:15 test /kernel: fdc0: direction bit not set > Feb 10 17:30:15 test /kernel: fdc0: cmd 3 failed at out byte 1 of 3 > Feb 10 17:30:15 test /kernel: atkbdc0: at port > 0x60,0x64 on isa0 > Feb 10 17:30:15 test /kernel: vga0: at port 0x3c0-0x3df > iomem 0xa0000-0xbffff on isa0 > Feb 10 17:30:15 test /kernel: sc0: at flags 0x100 on isa0 > Feb 10 17:30:15 test /kernel: sc0: VGA <16 virtual consoles, flags=0x300> > Feb 10 17:30:15 test /kernel: sio0: configured irq 4 not in bitmap of probed > irqs 0 > Feb 10 17:30:15 test /kernel: sio0 at port 0x3f8-0x3ff irq 4 flags 0x10 on > isa0 > Feb 10 17:30:15 test /kernel: sio0: type 8250 > Feb 10 17:30:15 test /kernel: sio1: configured irq 3 not in bitmap of probed > irqs 0 > Feb 10 17:30:15 test /kernel: ppc0: parallel port not found. > Feb 10 17:30:15 test /kernel: i4bipr: 4 IP over raw HDLC ISDN device(s) > attached (VJ header compression) > Feb 10 17:30:15 test /kernel: i4bctl: ISDN system control port attached > Feb 10 17:30:15 test /kernel: IP packet filtering initialized, divert > disabled, rule-based forwarding disabled, default to deny, logging limited > to 100 packets/entry by default > Feb 10 17:30:15 test /kernel: i4brbch: 4 raw B channel access device(s) > attached > Feb 10 17:30:15 test /kernel: i4b: ISDN call control device attached > Feb 10 17:30:15 test /kernel: i4btrc: 4 ISDN trace device(s) attached > Feb 10 17:30:15 test /kernel: ad0: 8063MB [16383/16/63] > at ata0-master UDMA66 > Feb 10 17:30:15 test /kernel: ad1: 19458MB [39535/16/63] at > ata1-master UDMA33 > Feb 10 17:30:15 test /kernel: Mounting root from ufs:/dev/ad0s1a > Feb 10 17:30:20 test su: igorp to root on /dev/ttyp0 > Feb 10 17:30:36 test isdnd[88]: DMN monitor opened from > localhost.inobject.com (127.0.0.1) rights 0x1 > Feb 10 17:30:47 test su: igorp to root on /dev/ttyp1 > Feb 10 17:31:56 test su: igorp to root on /dev/ttyp2 > Feb 10 17:33:16 test /kernel: i4b-L2 F_ILL: FSM function F_ILL executing > Feb 10 17:33:16 test /kernel: i4b-L2 i4b_next_l2state: FSM illegal state, > state = ST_EST_AW_TEI, event = EV_DL > Feb 10 17:33:16 test /kernel: i4b: unit 0, assigned TEI = 96 = 0x60 > Feb 10 17:33:16 test /kernel: ESTRQ! > Feb 10 17:33:22 test /kernel: i4b-L2 F_ILL: FSM function F_ILL executing > Feb 10 17:33:22 test /kernel: i4b-L2 i4b_next_l2state: FSM illegal state, > state = ST_EST_AW_TEI, event = EV_RXRR! > Feb 10 17:33:22 test /kernel: i4b-L2 i4b_rxd_i_frame: ERROR, state != (MF || > TR)! > Feb 10 17:33:22 test /kernel: i4b-L2 i4b_T200_timeout: unit 0, RC = 0 > Feb 10 17:33:22 test /kernel: i4b-L2 F_ILL: FSM function F_ILL executing > Feb 10 17:33:22 test /kernel: i4b-L2 i4b_next_l2state: FSM illegal state, > state = ST_EST_AW_TEI, event = EV_T200EXP! > Feb 10 17:33:22 test /kernel: i4b-L2 F_ILL: FSM function F_ILL executing > Feb 10 17:33:22 test /kernel: i4b-L2 i4b_next_l2state: FSM illegal state, > state = ST_EST_AW_TEI, event = EV_RXRR! > Feb 10 17:33:22 test /kernel: i4b-L2 F_ILL: FSM function F_ILL executing > Feb 10 17:33:22 test /kernel: i4b-L2 i4b_next_l2state: FSM illegal state, > state = ST_EST_AW_TEI, event = EV_RXRR! > Feb 10 17:33:22 test /kernel: i4b-L2 F_ILL: FSM function F_ILL executing > Feb 10 17:33:22 test /kernel: i4b-L2 i4b_next_l2state: FSM illegal state, > state = ST_EST_AW_TEI, event = EV_RXRR! > Feb 10 17:33:22 test /kernel: i4b-L3 T303_timeout: SETUP not answered, cr = > 2 > Feb 10 17:33:22 test /kernel: i4b-L2 i4b_dl_data_req: unit 0 ERROR in state > [ST_EST_AW_TEI], freeing mbuf > Feb 10 17:33:22 test /kernel: i4b-L3 T303_timeout: SETUP not answered, cr = > 47 > Feb 10 17:33:22 test /kernel: i4b-L3 next_l3state: FSM illegal state, state > = ST_OW - Out Wait EST, event = EV_T303EXP - T303 timeout! > Feb 10 17:33:22 test /kernel: i4b-L2 F_ILL: FSM function F_ILL executing > Feb 10 17:33:22 test /kernel: i4b-L2 i4b_next_l2state: FSM illegal state, > state = ST_EST_AW_TEI, event = EV_RXSABME! > Feb 10 17:33:22 test /kernel: i4b-L2 F_ILL: FSM function F_ILL executing > Feb 10 17:33:22 test /kernel: i4b-L2 i4b_next_l2state: FSM illegal state, > state = ST_EST_AW_TEI, event = EV_RXSABME! > Feb 10 17:33:25 test /kernel: i4b-L2 F_ILL: FSM function F_ILL executing > Feb 10 17:33:25 test /kernel: i4b-L2 i4b_next_l2state: FSM illegal state, > state = ST_EST_AW_TEI, event = EV_RXSABME! > Feb 10 17:33:25 test /kernel: i4b-L2 F_ILL: FSM function F_ILL executing > Feb 10 17:33:25 test /kernel: i4b-L2 i4b_next_l2state: FSM illegal state, > state = ST_EST_AW_TEI, event = EV_RXSABME! > Feb 10 17:33:31 test /kernel: i4b-L2 F_ILL: FSM function F_ILL executing > Feb 10 17:33:31 test /kernel: i4b-L2 i4b_next_l2state: FSM illegal state, > state = ST_EST_AW_TEI, event = EV_RXSABME! > Feb 10 17:33:31 test /kernel: i4b-L2 F_ILL: FSM function F_ILL executing > Feb 10 17:33:31 test /kernel: i4b-L2 i4b_next_l2state: FSM illegal state, > state = ST_EST_AW_TEI, event = EV_RXSABME! > Feb 10 17:33:31 test /kernel: i4b-L2 F_ILL: FSM function F_ILL executing > Feb 10 17:33:31 test /kernel: i4b-L2 i4b_next_l2state: FSM illegal state, > state = ST_EST_AW_TEI, event = EV_RXSABME! > Feb 10 17:33:31 test /kernel: i4b-L2 F_ILL: FSM function F_ILL executing > Feb 10 17:33:31 test /kernel: i4b-L2 i4b_next_l2state: FSM illegal state, > state = ST_EST_AW_TEI, event = EV_RXSABME! > Feb 10 17:41:53 test isdnd[88]: DMN monitor closed from > localhost.inobject.com (127.0.0.1) > Feb 10 17:41:54 test isdnd[88]: DMN monitor opened from > localhost.inobject.com (127.0.0.1) rights 0x1 > Feb 10 17:41:58 test isdnd[88]: DMN monitor closed from > localhost.inobject.com (127.0.0.1) > > su-2.04# uname -a > FreeBSD test.inobject.com 4.2-STABLE FreeBSD 4.2-STABLE #0: Sat Feb 10 > 16:18:57 GMT 2001 > root@test.inobject.com:/usr/src/sys/compile/IOBJ_ISDN_IPR i386 > > from log of my isdntrace : > > -- TE->NT - unit:0 - frame:000003 - time:10.02 17:33:16.400080 - > length:8 ------ > Dump:000 fc ff 03 0f a9 34 01 ff .....4.. > Q921: SAP=63 (TEI-Management), C, TEI=127, Ri=0x34a9, IdRequest, Ai=127 > > -- NT->TE - unit:0 - frame:000004 - time:10.02 17:33:16.410081 - > length:8 ------ > Dump:000 fe ff 03 0f a9 34 02 c1 .....4.. > Q921: SAP=63 (TEI-Management), C, TEI=127, Ri=0x34a9, IdAssign, Ai=96 > > -- TE->NT - unit:0 - frame:000005 - time:10.02 17:33:16.410081 - > length:3 ------ > Dump:000 00 c1 7f ... > Q921: SAP=0 (Call Control), C, TEI=96, U-Frame: SABME PF 1 > > -- NT->TE - unit:0 - frame:000006 - time:10.02 17:33:16.420079 - > length:3 ------ > Dump:000 00 c1 73 ..s > Q921: SAP=0 (Call Control), R, TEI=96, U-Frame: UA PF 1 > > -- TE->NT - unit:0 - frame:000007 - time:10.02 17:33:16.420079 - > length:39 ----- > Dump:000 00 c1 00 00 .... > Q921: SAP=0 (Call Control), C, TEI=96, I-Frame: N(S) 0 N(R) 0 P 0 > Dump:004 08 01 02 05 a1 04 02 88 90 18 01 83 6c 07 81 39 > ............l..9 > Dump:020 37 30 34 33 32 70 0c 81 38 37 30 37 35 30 30 33 > 70432p..87075003 > Dump:036 33 33 33 333 > Q931: pd=Q.931/I.451, cr=0x02 (from origination), message=SETUP: > [sending complete] > [bearer capability: > cap=unrestricted digital information > std=CCITT > rate=64 kbit/s > mode=circuit] > [channel id: channel=any channel (preferred)] > [calling party number: 970432 (type=unknown, plan=ISDN)] > [called party number: 87075003333 (type=unknown, plan=ISDN)] > > -- NT->TE - unit:0 - frame:000008 - time:10.02 17:33:16.450079 - > length:4 ------ > Dump:000 00 c1 01 02 .... > Q921: SAP=0 (Call Control), R, TEI=96, S-Frame: RR N(R) 1 PF 0 > <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<< Until here everything looks just fine. I have even compared the isdntrace of a successful connection attempt I've made with yours, and despite the phone numbers, they are almost identical. > -- NT->TE - unit:0 - frame:000009 - time:10.02 17:33:16.610080 - > length:15 ----- > Dump:000 02 c1 00 02 .... > Q921: SAP=0 (Call Control), C, TEI=96, I-Frame: N(S) 0 N(R) 1 P 0 > Dump:004 08 01 82 7d 08 02 82 e4 14 01 01 ...}....... > Q931: pd=Q.931/I.451, cr=0x02 (from destination), message=STATUS: > [cause: 100: Invalid information element contents (Q.850) > (location=public network serving local user, std=CCITT)] > [call state: Std=CCITT, State=Call initiated] > <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<< This is (I think) an exchange generated message saying it disliked something on the previous `SETUP' frame. My guess are the phone numbers since the other bytes on the hex dump are the same of my own `SETUP'. Double check them (both originating and destination). Another possibility is the bearer capability: perhaps it wants a more `strict' one, stating it is a `DATA' call. This message apparently didn't get well on the L2/L3 FSMs because it remained unacknoledged as we can see from the 3 frames below. > -- NT->TE - unit:0 - frame:000010 - time:10.02 17:33:17.760092 - > length:4 ------ > Dump:000 02 c1 01 03 .... > Q921: SAP=0 (Call Control), C, TEI=96, S-Frame: RR N(R) 1 PF 1 > > -- NT->TE - unit:0 - frame:000011 - time:10.02 17:33:18.960104 - > length:4 ------ > Dump:000 02 c1 01 03 .... > Q921: SAP=0 (Call Control), C, TEI=96, S-Frame: RR N(R) 1 PF 1 > > -- NT->TE - unit:0 - frame:000012 - time:10.02 17:33:20.160117 - > length:4 ------ > Dump:000 02 c1 01 03 .... > Q921: SAP=0 (Call Control), C, TEI=96, S-Frame: RR N(R) 1 PF 1 > <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<< I don't know if the following ones are allowed by the specs: apparently the exchange is trying to re-establish the connection (L2). I4B doesn't seems to like it. > -- NT->TE - unit:0 - frame:000013 - time:10.02 17:33:21.360130 - > length:3 ------ > Dump:000 02 c1 7f ... > Q921: SAP=0 (Call Control), C, TEI=96, U-Frame: SABME PF 1 > > -- NT->TE - unit:0 - frame:000014 - time:10.02 17:33:22.560143 - > length:3 ------ > Dump:000 02 c1 7f ... > Q921: SAP=0 (Call Control), C, TEI=96, U-Frame: SABME PF 1 > > -- NT->TE - unit:0 - frame:000015 - time:10.02 17:33:23.760155 - > length:3 ------ > Dump:000 02 c1 7f ... > Q921: SAP=0 (Call Control), C, TEI=96, U-Frame: SABME PF 1 > > -- NT->TE - unit:0 - frame:000016 - time:10.02 17:33:24.960168 - > length:3 ------ > Dump:000 02 c1 7f ... > Q921: SAP=0 (Call Control), C, TEI=96, U-Frame: SABME PF 1 > <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<< Concluding that something wrong occurred at the TE, the exchange trys to restart the connection by reassuring the TEI of the caller (your machine). > -- NT->TE - unit:0 - frame:000017 - time:10.02 17:33:26.160180 - > length:8 ------ > Dump:000 fe ff 03 0f 00 00 04 c1 ........ > Q921: SAP=63 (TEI-Management), C, TEI=127, Ri=0x0000, IdCheckReq, Ai=96 > > -- TE->NT - unit:0 - frame:000018 - time:10.02 17:33:26.160180 - > length:8 ------ > Dump:000 fc ff 03 0f 1b fe 05 c1 ........ > Q921: SAP=63 (TEI-Management), C, TEI=127, Ri=0xfe1b, IdCheckResp, Ai=96 > <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<< Then, it trys again to get the L2 connection back. I think the L2 FSM, once in the error state, does not allow the receive of a `SABME' frame. Again, I don't know if what the exchange is trying to do is even correct, since it is not the originator. I'm still digging thru L1 specs (thanks Hellmuth for the pointers) in my ISDN learning curve... 8-) These are my conclusions made from the observation of your logs. They are by no means irrefutable. If someone on the list can give us any other clue, I'd be glad to hear. > -- NT->TE - unit:0 - frame:000019 - time:10.02 17:33:26.180181 - > length:3 ------ > Dump:000 02 c1 7f ... > Q921: SAP=0 (Call Control), C, TEI=96, U-Frame: SABME PF 1 > > -- NT->TE - unit:0 - frame:000020 - time:10.02 17:33:27.360193 - > length:3 ------ > Dump:000 02 c1 7f ... > Q921: SAP=0 (Call Control), C, TEI=96, U-Frame: SABME PF 1 > > -- NT->TE - unit:0 - frame:000021 - time:10.02 17:33:28.550205 - > length:3 ------ > Dump:000 02 c1 7f ... > Q921: SAP=0 (Call Control), C, TEI=96, U-Frame: SABME PF 1 > > -- NT->TE - unit:0 - frame:000022 - time:10.02 17:33:29.750218 - > length:3 ------ > Dump:000 02 c1 7f ... > Q921: SAP=0 (Call Control), C, TEI=96, U-Frame: SABME PF 1 > > -- NT->TE - unit:0 - frame:000023 - time:10.02 17:33:30.960231 - > length:8 ------ > Dump:000 fe ff 03 0f 00 00 04 c1 ........ > Q921: SAP=63 (TEI-Management), C, TEI=127, Ri=0x0000, IdCheckReq, Ai=96 > > -- TE->NT - unit:0 - frame:000024 - time:10.02 17:33:30.960231 - > length:8 ------ > Dump:000 fc ff 03 0f fc d0 05 c1 ........ > Q921: SAP=63 (TEI-Management), C, TEI=127, Ri=0xd0fc, IdCheckResp, Ai=96 > > -- NT->TE - unit:0 - frame:000025 - time:10.02 17:33:41.160338 - > length:8 ------ > Dump:000 fe ff 03 0f 00 00 04 c1 ........ > Q921: SAP=63 (TEI-Management), C, TEI=127, Ri=0x0000, IdCheckReq, Ai=96 > > -- TE->NT - unit:0 - frame:000026 - time:10.02 17:33:41.160338 - > length:8 ------ > Dump:000 fc ff 03 0f 00 53 05 c1 .....S.. > Q921: SAP=63 (TEI-Management), C, TEI=127, Ri=0x5300, IdCheckResp, Ai=96 > > -- NT->TE - unit:0 - frame:000027 - time:10.02 17:34:54.351110 - > length:8 ------ > Dump:000 fe ff 03 0f 00 00 04 c5 ........ > Q921: SAP=63 (TEI-Management), C, TEI=127, Ri=0x0000, IdCheckReq, Ai=98 > > -- NT->TE - unit:0 - frame:000028 - time:10.02 17:35:43.141625 - > length:8 ------ > Dump:000 fe ff 03 0f 00 00 04 c1 ........ > Q921: SAP=63 (TEI-Management), C, TEI=127, Ri=0x0000, IdCheckReq, Ai=96 > > my isdnd.rc : > > system > > acctall = on > acctfile = /var/log/isdnd.acct > useacctfile = yes > isdntime = on > monitor-allowed = yes > monitor = "127.0.0.1" > monitor-access = fullcmd > beepconnect = on > > controller > protocol = dss1 > > entry > name = userppp0 > usrdevicename = rbch > usrdeviceunit = 0 > isdncontroller = 0 > isdnchannel = -1 > local-phone-dialout = 970432 > local-phone-incoming = 970432 > remote-phone-dialout = 87075003333 > remote-phone-incoming = * > b1protocol = hdlc > dialin-reaction = ignore > dialout-type = normal > direction = out > dialrandincr = on > dialretries = -1 > recoverytime = 1 > usedown = off > downtries = 10 > downtime = 30 > #idle-algorithm-outgoing = fix-unit-size > idle-algorithm-outgoing = var-unit-size > idletime-incoming = 900 > idletime-outgoing = 900 > unitlengthsrc = conf > unitlength = 0 > remdial-handling = first > > entry > name = userppp1 > usrdevicename = rbch > usrdeviceunit = 1 > isdncontroller = 0 > isdnchannel = -1 > local-phone-dialout = 970432 > local-phone-incoming = 970432 > remote-phone-dialout = 87075003333 > remote-phone-incoming = * > b1protocol = hdlc > dialin-reaction = ignore > dialout-type = normal > direction = out > dialrandincr = on > dialretries = -1 > recoverytime = 1 > usedown = off > downtries = 10 > downtime = 30 > #idle-algorithm-outgoing = fix-unit-size > idle-algorithm-outgoing = var-unit-size > idletime-incoming = 900 > idletime-outgoing = 900 > unitlengthsrc = conf > unitlength = 0 > remdial-handling = first > > my ppp.conf : > > default: > isdn: > set log phase chat lcp ipcp ccp command > set phone 87075003333 > set authname name > set authkey password > # set enddisc mac > enable lqr > set reconnect 3 5 > set redial 3 10 > set lqrperiod 45 > disable pred1 deflate mppe > deny pred1 deflate mppe > set timeout 60 300 > set dial > set login > set logout > set hangup > set device /dev/i4brbch0 /dev/i4brbch1 > set speed sync > enable dns > set ifaddr 212.113.40.176/0 10.3.1.20/0 > add! default hisaddr > set mrru 1500 > set mru 1504 > clone 1,2 > link deflink rm > link * set mode auto > set autoload 10 80 30 > set server /tmp/ppp-isdn "" 0177 > To Unsubscribe: send mail to majordomo@FreeBSD.org with "unsubscribe freebsd-isdn" in the body of the message