Date: Wed, 23 Sep 1998 21:21:24 +0200 (CEST) From: Joachim Kuebart <joki@kuebart.stuttgart.netsurf.de> To: isdn@FreeBSD.ORG Cc: hm@kts.org Subject: Problem with Q.931 implementation Message-ID: <199809231921.VAA00494@shire.domestic.de>
next in thread | raw e-mail | index | archive | help
Hi,
for a few weeks now, I've got the following problem:
The log files lead me to conclude that some Q.931 isn't properly
understood by the driver. Due to some follow-up errors this leads to a
reboot as soon as a connection succeeds.
This version of i4b:
-rw-r--r-- 1 root bin 525165 10 Jul 10:10 i4b-00.63-alpha-100798.tgz
This is the debug log:
1st attempt
-------------
Sep 23 21:05:44 shire /kernel: isppp0: lcp open(initial)
Sep 23 21:05:44 shire /kernel: isppp0: phase establish
Sep 23 21:05:44 shire isdnd[214]: DBG msg_dialout: dial req from isppp, unit 0
Sep 23 21:05:44 shire isdnd[214]: DBG find_device: found entry 0!
Sep 23 21:05:44 shire isdnd[214]: DBG FSM event [msg-dialout]: [idle => dialing]
Sep 23 21:05:44 shire isdnd[214]: DBG F_DIAL: local dial out request
Sep 23 21:05:44 shire isdnd[214]: DBG select_first_dialno: only one no, no = 726704
Sep 23 21:05:44 shire isdnd[214]: CHD 00004 Netsurf rate 240 sec/unit (rate)
Sep 23 21:05:44 shire isdnd[214]: CHD 00004 Netsurf dialing out from 653706 to 726704
Sep 23 21:05:44 shire isdnd[214]: CHD 00004 Netsurf outgoing call proceeding (ctl 0, ch 0)
Sep 23 21:05:45 shire isdnd[214]: CHD 00004 Netsurf incoming alert
Sep 23 21:05:45 shire /kernel: isppp0: Up event
Sep 23 21:05:45 shire /kernel: isppp0: lcp up(starting)
Sep 23 21:05:45 shire /kernel: isppp0: lcp output <conf-req id=0x9 len=15 5-6-36-f-c3-ce-3-5-c2-23-5>
Sep 23 21:05:45 shire isdnd[214]: DBG msg_charging: 1 unit(s) (estimated)
Sep 23 21:05:45 shire /kernel: i4b-L3-i4b_decode_q931_message: STATUS message
^^^^^^^^^^^^^^^^^^^^^^^^^^
First error condition
Sep 23 21:05:45 shire /kernel: i4b-L2-i4b_i_frame_queued_up: V(S) == ((V(A) + k) & 127)!
Sep 23 21:05:45 shire /kernel: i4b-L2-i4b_i_frame_queued_up: state = ST_MULTIFR
Sep 23 21:05:45 shire /kernel: i4b-L2-i4b_print_l2var: unit0 V(R)=13, V(S)=11, V(A)=10,ACKP=0,PBSY=0,OBSY=0
Sep 23 21:05:45 shire isdnd[214]: CHD 00004 Netsurf outgoing call active (ctl 0, ch 0)
Sep 23 21:05:45 shire /kernel: isppp0: lcp down(req-sent)
Sep 23 21:05:45 shire /kernel: isppp0: Down event (carrier loss)
Sep 23 21:05:45 shire /kernel: isppp0: lcp close(starting)
Sep 23 21:05:46 shire /kernel: isppp0: phase dead
Sep 23 21:05:45 shire isdnd[214]: DBG exec_prog: popmail, args: 00004 Netsurf outgoing call active (ctl 0, ch 0)
Sep 23 21:05:45 shire isdnd[214]: DBG FSM event [msg-con-act-ind]: [dialing => connected]
Sep 23 21:05:45 shire isdnd[214]: DBG F_DOK: dial out ok
Sep 23 21:05:45 shire isdnd[214]: DBG select_this_dialno: index = 0, no = 726704
Sep 23 21:05:45 shire isdnd[214]: DBG normal child (pid=1384) termination, exitstat = 0
Sep 23 21:05:45 shire isdnd[214]: DBG msg_charging: 1 unit(s) (AOCE)
Sep 23 21:05:45 shire isdnd[214]: CHD 00004 Netsurf outgoing call disconnected (remote)
Sep 23 21:05:45 shire isdnd[214]: CHD 00004 Netsurf cause 101: Message not compatible with call state (Q.850)
Sep 23 21:05:45 shire isdnd[214]: CHD 00004 Netsurf charging: 1 units, 0 seconds
Sep 23 21:05:45 shire isdnd[214]: CHD 00004 Netsurf accounting: in 0, out 19 (in 0, out 0)
Sep 23 21:05:45 shire isdnd[214]: DBG FSM event [msg-disc-ind]: [connected => idle]
Sep 23 21:05:45 shire isdnd[214]: DBG F_IDIS: disconnect indication
2nd attempt
-------------
Sep 23 21:05:52 shire /kernel: isppp0: lcp open(initial)
Sep 23 21:05:52 shire /kernel: isppp0: phase establish
Sep 23 21:05:52 shire isdnd[214]: DBG msg_dialout: dial req from isppp, unit 0
Sep 23 21:05:52 shire isdnd[214]: DBG find_device: found entry 0!
Sep 23 21:05:52 shire isdnd[214]: DBG FSM event [msg-dialout]: [idle => dialing]
Sep 23 21:05:52 shire isdnd[214]: DBG F_DIAL: local dial out request
Sep 23 21:05:52 shire isdnd[214]: DBG select_first_dialno: only one no, no = 726704
Sep 23 21:05:52 shire isdnd[214]: CHD 00005 Netsurf rate 240 sec/unit (rate)
Sep 23 21:05:52 shire isdnd[214]: CHD 00005 Netsurf dialing out from 653706 to 726704
Sep 23 21:05:52 shire /kernel: i4b-L3-i4b_decode_q931: cannot find calldescriptor for cr = 0x65, crflag = 0x1, msg = 0x4d, frame = 0x4d 0x8 0x2 0x82 0xd1
^^^^^^^^^^^^^^^^^^^^^
Now something weired is happening...
Sep 23 21:05:56 shire /kernel: i4b-L3-T303_timeout: SETUP not answered, cr = 41
Sep 23 21:05:56 shire /kernel: i4b-L3-i4b_decode_q931: cannot find calldescriptor for cr = 0x65, crflag = 0x1, msg = 0x4d, frame = 0x4d 0x8 0x2 0x82 0xd1
Sep 23 21:05:56 shire isdnd[214]: CHD 00005 Netsurf outgoing call proceeding (ctl 0, ch 0)
Sep 23 21:05:57 shire isdnd[214]: CHD 00005 Netsurf incoming alert
Sep 23 21:05:57 shire /kernel: isppp0: Up event
Sep 23 21:05:57 shire /kernel: isppp0: lcp up(starting)
Sep 23 21:05:57 shire /kernel: isppp0: lcp output <conf-req id=0xa len=15 5-6-36-f-c3-ce-3-5-c2-23-5>
Sep 23 21:05:57 shire /kernel: isppp0: lcp input(req-sent): <conf-req id=0x1 len=31 0-4-0-0-1-4-5-f4-3-5-c2-23-5-11-4-5-f4-13-a-1-73-74-61-63-6b-30-31>
Sep 23 21:05:57 shire /kernel: isppp0: lcp parse opts: 0x0 [rej] mru auth-proto 0x11 [rej] 0x13 [rej] send conf-rej
Sep 23 21:05:57 shire /kernel: isppp0: lcp output <conf-rej id=0x1 len=22 0-4-0-0-11-4-5-f4-13-a-1-73-74-61-63-6b-30-31>
Sep 23 21:05:57 shire /kernel: isppp0: lcp input(req-sent): <conf-rej id=0xa len=9 3-5-c2-23-5>
Sep 23 21:05:57 shire /kernel: isppp0: lcp rej opts: auth-proto [don't insist on auth for callout]
Sep 23 21:05:57 shire /kernel: isppp0: lcp output <conf-req id=0xb len=10 5-6-36-f-c3-ce>
Sep 23 21:05:58 shire /kernel: isppp0: lcp input(req-sent): <conf-req id=0x2 len=13 1-4-5-f4-3-5-c2-23-5>
Sep 23 21:05:58 shire /kernel: isppp0: lcp parse opts: mru auth-proto
Sep 23 21:05:58 shire /kernel: isppp0: lcp parse opt values: mru 1524 auth-proto send conf-ack
Sep 23 21:05:58 shire /kernel: isppp0: lcp output <conf-ack id=0x2 len=13 1-4-5-f4-3-5-c2-23-5>
Sep 23 21:05:58 shire /kernel: isppp0: lcp input(ack-sent): <conf-ack id=0xb len=10 5-6-36-f-c3-ce>
Sep 23 21:05:58 shire /kernel: isppp0: lcp tlu
Sep 23 21:05:58 shire /kernel: isppp0: phase authenticate
Sep 23 21:05:57 shire isdnd[214]: DBG msg_charging: 1 unit(s) (estimated)
Sep 23 21:05:58 shire /kernel: isppp0: chap input <challenge id=0x1 len=28 name=p400-e1 value-size=16 value= ee-4d-a1-b9-f1-59-7-b8-a1-a5-7a-8f-ec-c8-10-a1>
Sep 23 21:05:58 shire /kernel: isppp0: chap output <response id=0x1 len=29 10-5e-97-c5-29-ad-9d-11-ff-39-67-4f-37-b3-f8-b3-e2-50-6b-75-65-62-61-72-74>
Sep 23 21:05:58 shire /kernel: isppp0: chap success: \x0
Sep 23 21:05:58 shire /kernel: isppp0: phase network
Sep 23 21:05:58 shire /kernel: isppp0: ipcp open(initial)
Sep 23 21:05:58 shire /kernel: isppp0: ipcp up(starting)
Sep 23 21:05:58 shire /kernel: isppp0: ipcp output <conf-req id=0xc len=10 3-6-0-0-0-0>
Sep 23 21:05:58 shire /kernel: isppp0: ipcp input(req-sent): <conf-req id=0x1 len=16 2-6-0-2d-f-1-3-6-c2-40-4-7>
Sep 23 21:05:58 shire /kernel: isppp0: ipcp parse opts: compression [rej] address send conf-rej
Sep 23 21:05:58 shire /kernel: isppp0: ipcp output <conf-rej id=0x1 len=10 2-6-0-2d-f-1>
Sep 23 21:05:58 shire /kernel: isppp0: ipcp input(req-sent): <conf-nak id=0xc len=10 3-6-c2-e9-d8-b6>
Sep 23 21:05:58 shire /kernel: isppp0: ipcp nak opts: address [wantaddr 194.233.216.182] [agree]
Sep 23 21:05:59 shire /kernel: isppp0: ipcp output <conf-req id=0xd len=10 3-6-c2-e9-d8-b6>
Sep 23 21:05:59 shire /kernel: isppp0: ipcp input(req-sent): <conf-req id=0x2 len=10 3-6-c2-40-4-7>
Sep 23 21:05:59 shire /kernel: isppp0: ipcp parse opts: address
Sep 23 21:05:59 shire /kernel: isppp0: ipcp parse opt values: address 0.0.0.1 [ack] send conf-ack
Sep 23 21:05:59 shire /kernel: isppp0: ipcp output <conf-ack id=0x2 len=10 3-6-c2-40-4-7>
Sep 23 21:05:59 shire /kernel: isppp0: ipcp input(ack-sent): <conf-ack id=0xd len=10 3-6-c2-e9-d8-b6>
Sep 23 21:05:59 shire /kernel: isppp0: ipcp tlu
Sep 23 21:08:00 shire syslogd: restart
^^^^^^^
And now this... :-(
Sep 23 21:08:00 shire /kernel: Copyright (c) 1992-1998 FreeBSD Inc.
Sep 23 21:08:00 shire /kernel: Copyright (c) 1982, 1986, 1989, 1991, 1993
Sep 23 21:08:00 shire /kernel: The Regents of the University of California. All rights reserved.
Sep 23 21:08:01 shire /kernel:
Sep 23 21:08:01 shire /kernel: FreeBSD 2.2.6-STABLE #0: Wed Sep 23 19:45:55 CEST 1998
...
This is the isdn part of dmesg:
isic0 at 0x240 irq 10 flags 0x8 on isa
isic0: AVM A1 or AVM Fritz!Card
isic0: ISAC 2085 Version A1/A2 or 2086/2186 Version 1.1 (IOM-2) (Addr=0x1620)
isic0: HSCX 82525 or 21525 Version 2.1 (AddrA=0x620, AddrB=0xe20)
i4b: ISDN call control device attached
i4bisppp: 4 ISDN SyncPPP device(s) attached
i4bctl: ISDN system control port attached
i4bipr: 4 IP over raw HDLC ISDN device(s) attached
i4btel: 2 ISDN telephony interface device(s) attached
i4brbch: 4 raw B channel access device(s) attached
i4btrc: 4 ISDN trace device(s) attached
cu Jo
---------------------------------------------------------------------
FreeBSD: The Power to Serve <http://www.freebsd.org>;
Joachim Kuebart
Tel: +49 711 653706 Replicants are like any other machine --
Germany they're either a benefit or a hazard.
To Unsubscribe: send mail to majordomo@FreeBSD.org
with "unsubscribe freebsd-isdn" in the body of the message
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?199809231921.VAA00494>