Date: Sat, 01 Aug 1998 10:25:17 +0200 From: Marc van Kempen <marc@bowtie.nl> To: hm@hcs.de Cc: freebsd-isdn@FreeBSD.ORG Subject: Re: Tracing Kernel code (isppp) & possible isdnd bug Message-ID: <199808010825.KAA17791@bowtie.nl> In-Reply-To: hm's message of Fri, 31 Jul 1998 09:11:50 %2B0200. <m0z29Ly-0000f6C@hcswork.hcs.de>
next in thread | previous in thread | raw e-mail | index | archive | help
In message <m0z29Ly-0000f6C@hcswork.hcs.de>, Hellmuth Michaelis writes: >From the keyboard of Gerald Heinig: > >> Hellmuth Michaelis wrote: >> >> > >From the keyboard of Gerald Heinig: >> > >> > > Basically, i4b dials, *seems* to get an active connection and then releases the >> > > line about 2 or 3 seconds afterwards. It then re-dials and says it has an active >> > > connection, only to release it again after 2-3 seconds and so on, up until 10 >> > > tries, when it stops. I've emphasised the "seems" because I'm not actually sure >> > > whether the connection could really be established. >> > >> > I'd like to see an isdntrace output of this. >> >> Comin' up.... >> >> I'll make a proper effort from now on to get good traces. The one I've attached is >> one I did more or less out of idle curiosity, but as far as I can remember, the >> problem came up in this trace. > >At the ISDN level i don't see any problem. The local machine builds up a >connection to the remote successfully. After some time, the _local_ machine >disconnects in a normal way from the remote site. > This sounds an awful lot like my problem, I was just going to ask here how to trace a problem like this. I'll include my sppp debug output for starters, Aug 1 10:01:04 schopenhauer /kernel: isppp0: lcp open(initial) Aug 1 10:01:04 schopenhauer /kernel: isppp0: phase establish Aug 1 10:01:04 schopenhauer /kernel: isppp0: Up event Aug 1 10:01:04 schopenhauer /kernel: isppp0: lcp up(starting) Aug 1 10:01:04 schopenhauer /kernel: isppp0: lcp output <conf-req id=0x30 len=10 5-6-35-c6-2-e1> Aug 1 10:01:05 schopenhauer /kernel: isppp0: lcp input(req-sent): <conf-req id=0x1 len=14 5-6-b9-4c-d3-2c-3-4-c0-23> Aug 1 10:01:05 schopenhauer /kernel: isppp0: lcp parse opts: magic auth-proto Aug 1 10:01:05 schopenhauer /kernel: isppp0: lcp parse opt values: magic 0xb94cd32c auth-proto send conf-ack Aug 1 10:01:05 schopenhauer /kernel: isppp0: lcp output <conf-ack id=0x1 len=14 5-6-b9-4c-d3-2c-3-4-c0-23> Aug 1 10:01:05 schopenhauer /kernel: isppp0: lcp input(ack-sent): <conf-ack id=0x30 len=10 5-6-35-c6-2-e1> Aug 1 10:01:05 schopenhauer /kernel: isppp0: lcp tlu Aug 1 10:01:05 schopenhauer /kernel: isppp0: phase authenticate Aug 1 10:01:05 schopenhauer /kernel: isppp0: pap output <req id=0x31 len=20 7-50-62-6f-77-74-69-65-7-42-26-74-33-38-4d-69> Aug 1 10:01:05 schopenhauer /kernel: isppp0: pap success: 3U Aug 1 10:01:05 schopenhauer /kernel: isppp0: phase network Aug 1 10:01:05 schopenhauer /kernel: isppp0: ipcp open(stopped) Aug 1 10:01:05 schopenhauer /kernel: isppp0: lcp close(opened) Aug 1 10:01:05 schopenhauer /kernel: isppp0: phase terminate Aug 1 10:01:05 schopenhauer /kernel: isppp0: lcp output <term-req id=0x32 len=4> Aug 1 10:01:05 schopenhauer /kernel: isppp0: lcp input(closing): <term-ack id=0x2 len=4> Aug 1 10:01:05 schopenhauer /kernel: isppp0: phase dead Aug 1 10:01:05 schopenhauer /kernel: isppp0: lcp down(closed) Aug 1 10:01:05 schopenhauer /kernel: isppp0: Down event (carrier loss) etc... This just happened while I had been making several connections already (regular timeouts from the dial-up stuff). From one moment to the other it stopped working. A reboot seems to solve it every time, a restart of the isdn daemon, or ifconfig'ing the isppp0 interface up/down doesn't seem to affect the problem. I'll send an isdntrace too, next time it happens. Here is some more output from my messages file, I think this is the output from 'isdndebug -l 4 -m'. Aug 1 09:51:14 schopenhauer /kernel: isppp0: phase establish Aug 1 09:51:14 schopenhauer /kernel: i4b-L4-reserve_cd: found free cd - index=0 cdid=79 Aug 1 09:51:14 schopenhauer /kernel: i4b-L4-cd_by_cdid: found cdid - index=0 cdid=79 cr=23 Aug 1 09:51:14 schopenhauer /kernel: i4b-L4-i4bioctl: I4B_CONNECT_REQ times, unitlen=150 idle=30 earlyhup=5 Aug 1 09:51:14 schopenhauer /kernel: i4b-L4-cd_by_cdid: found cdid - index=0 cdid=79 cr=12 Aug 1 09:51:15 schopenhauer /kernel: i4b-L4-cd_by_unitcr: found cd, index=0 cdid=79 cr=12 Aug 1 09:51:15 schopenhauer /kernel: i4b-L4-cd_by_unitcr: found cd, index=0 cdid=79 cr=12 Aug 1 09:51:15 schopenhauer /kernel: i4b-L4-i4b_l4_connect_active_ind: last_active/connect_time=901957875 Aug 1 09:51:15 schopenhauer /kernel: i4b-L4-i4b_l4_setup_timeout: 901957875: outgoing-call, start 115 sec nocheck window Aug 1 09:51:16 schopenhauer /kernel: isppp0: phase authenticate Aug 1 09:51:16 schopenhauer /kernel: isppp0: phase network Aug 1 09:51:16 schopenhauer /kernel: isppp0: phase terminate Aug 1 09:51:16 schopenhauer /kernel: isppp0: phase dead Aug 1 09:51:16 schopenhauer /kernel: i4b-L4-cd_by_cdid: found cdid - index=0 cdid=79 cr=12 Aug 1 09:51:16 schopenhauer /kernel: i4b-L4-cd_by_unitcr: found cd, index=0 cdid=79 cr=12 Aug 1 09:51:16 schopenhauer /kernel: i4b-L4-freecd_by_cd: releasing cd - index=0 cdid=79 cr=12 I'll attach the output from 'isdndebug -m' from another occasion, I didn't enable that output this time. (I couldn't exactly determine where to start listing the debug output, so I may have included a bit more context than neccessary, sorry if it's too long). Jul 30 09:39:39 schopenhauer /kernel: i4b-L2-i4b_T200_stop: unit 0 Jul 30 09:39:39 schopenhauer /kernel: i4b-L2-i4b_next_l2state: FSM S-event [EV_RXRR]: [ST_MULTIFR => ST_MULTIFR] Jul 30 09:39:39 schopenhauer /kernel: isppp0: phase authenticate Jul 30 09:39:39 schopenhauer /kernel: isppp0: phase network Jul 30 09:39:39 schopenhauer /kernel: isppp0: phase terminate Jul 30 09:39:39 schopenhauer /kernel: isppp0: phase dead Jul 30 09:39:39 schopenhauer /kernel: i4b-L4-cd_by_cdid: found cdid - index=0 cdid=124 cr=41 Jul 30 09:39:39 schopenhauer /kernel: i4b-L3-next_l3state: L3 FSM event [EV_DISCRQ - L4 DISC REQ]: [ST_U10 - Active => ST_U11 - $ Jul 30 09:39:39 schopenhauer /kernel: i4b-L3-F_DCRQ: FSM function F_DCRQ executing Jul 30 09:39:39 schopenhauer /kernel: i4b-L3-i4b_l3_tx_disconnect: tx DISCONNECT for cr 41 Jul 30 09:39:39 schopenhauer /kernel: i4b-L2-i4b_dl_data_req: unit 0 Jul 30 09:39:39 schopenhauer /kernel: i4b-L1-ph_data_req: ISAC_TX_ACTIVE set Jul 30 09:39:39 schopenhauer /kernel: i4b-L2-i4b_T200_start: unit 0 Jul 30 09:39:40 schopenhauer /kernel: i4b-L3-T305_start: cr = 41 Jul 30 09:39:40 schopenhauer /kernel: i4b-L1-isic_isac_irq: ista =0x10 Jul 30 09:39:40 schopenhauer /kernel: i4b-L1-isic_isac_irq: ista =0x80 Jul 30 09:39:40 schopenhauer /kernel: i4b-L2-i4b_rxd_s_frame: rx'd RR, N(R) = 27 Jul 30 09:39:40 schopenhauer /kernel: i4b-L2-F_MF17: FSM function F_MF17 executing Jul 30 09:39:40 schopenhauer /kernel: i4b-L2-i4b_T200_stop: unit 0 Jul 30 09:39:40 schopenhauer /kernel: i4b-L2-i4b_next_l2state: FSM S-event [EV_RXRR]: [ST_MULTIFR => ST_MULTIFR] Jul 30 09:39:40 schopenhauer /kernel: i4b-L1-isic_hscx_irq: received invalid Frame Jul 30 09:39:40 schopenhauer /kernel: i4b-L1-isic_hscx_irq: CRC check failed Jul 30 09:39:40 schopenhauer /kernel: i4b-L1-isic_hscx_irq: Receive message aborted Jul 30 09:39:40 schopenhauer /kernel: i4b-L1-isic_isac_irq: ista =0x80 Jul 30 09:39:40 schopenhauer /kernel: i4b-L3-i4b_decode_q931: Call Ref, len 1, val 41, flag 1 Jul 30 09:39:40 schopenhauer /kernel: i4b-L4-cd_by_unitcr: found cd, index=0 cdid=124 cr=41 Jul 30 09:39:40 schopenhauer /kernel: i4b-L3-i4b_decode_q931_message: RELEASE message Jul 30 09:39:40 schopenhauer /kernel: i4b-L3-i4b_decode_q931_codeset0: IEI_CAUSE = 16 Jul 30 09:39:40 schopenhauer /kernel: i4b-L3-next_l3state: L3 FSM event [EV_RELEASE - rxd REL]: [ST_U11 - Disc Req => ST_U0 - Nu$ Jul 30 09:39:40 schopenhauer /kernel: i4b-L3-F_11J: FSM function F_11J executing Jul 30 09:39:40 schopenhauer /kernel: i4b-L3-T305_stop: cr = 41 Jul 30 09:39:40 schopenhauer /kernel: i4b-L3-i4b_l3_tx_release_complete: tx RELEASE COMPL for cr 41 Jul 30 09:39:40 schopenhauer /kernel: i4b-L2-i4b_dl_data_req: unit 0 Jul 30 09:39:40 schopenhauer /kernel: i4b-L1-ph_data_req: ISAC_TX_ACTIVE set Jul 30 09:39:40 schopenhauer /kernel: i4b-L2-i4b_T200_start: unit 0 Jul 30 09:39:40 schopenhauer /kernel: i4b-L1-isic_bchannel_setup: unit=0, channel=0, deactivate Jul 30 09:39:40 schopenhauer /kernel: i4b-L4-freecd_by_cd: releasing cd - index=0 cdid=124 cr=41 Jul 30 09:39:40 schopenhauer /kernel: i4b-L1-isic_isac_irq: ista =0x10 Jul 30 09:39:40 schopenhauer /kernel: i4b-L1-isic_isac_irq: ista =0x80 Jul 30 09:39:40 schopenhauer /kernel: i4b-L2-i4b_rxd_s_frame: rx'd RR, N(R) = 28 Jul 30 09:39:40 schopenhauer /kernel: i4b-L2-F_MF17: FSM function F_MF17 executing Jul 30 09:39:40 schopenhauer /kernel: i4b-L2-i4b_T200_stop: unit 0 Jul 30 09:39:40 schopenhauer /kernel: i4b-L2-i4b_next_l2state: FSM S-event [EV_RXRR]: [ST_MULTIFR => ST_MULTIFR] Jul 30 09:39:49 schopenhauer /kernel: i4b-L1-isic_isac_irq: ista =0x80 Jul 30 09:39:49 schopenhauer /kernel: i4b-L2-i4b_rxd_u_frame: DISC, sapi = 0, tei = 65 Jul 30 09:39:49 schopenhauer /kernel: i4b-L2-i4b_next_l2state: FSM event [EV_RXDISC]: [ST_MULTIFR/6 => ST_TEI_ASGD/3] Jul 30 09:39:49 schopenhauer /kernel: i4b-L2-F_MF08: FSM function F_MF08 executing Jul 30 09:39:49 schopenhauer /kernel: i4b-L2-i4b_tx_ua: tx UA, tei = 65 Jul 30 09:39:49 schopenhauer /kernel: i4b-L1-ph_data_req: ISAC_TX_ACTIVE set Jul 30 09:39:49 schopenhauer /kernel: i4b-L2-i4b_T200_stop: unit 0 Jul 30 09:39:49 schopenhauer /kernel: i4b-L2-i4b_next_l2state: FSM executing postfsmfunc! Jul 30 09:39:49 schopenhauer /kernel: i4b-L3-i4b_dl_release_ind: unit=0 DL released! Jul 30 09:39:49 schopenhauer /kernel: i4b-L3-i4b_dl_release_ind: no cdid for unit 0 found Jul 30 09:39:49 schopenhauer /kernel: i4b-L1-isic_isac_irq: ista =0x10 Jul 30 09:39:58 schopenhauer /kernel: isppp0: phase establish Jul 30 09:39:58 schopenhauer /kernel: i4b-L4-reserve_cd: found free cd - index=0 cdid=125 Jul 30 09:39:58 schopenhauer /kernel: i4b-L4-cd_by_cdid: found cdid - index=0 cdid=125 cr=41 Jul 30 09:39:58 schopenhauer /kernel: i4b-L4-i4bioctl: I4B_CONNECT_REQ times, unitlen=90 idle=30 earlyhup=5 Jul 30 09:39:58 schopenhauer /kernel: i4b-L4-cd_by_cdid: found cdid - index=0 cdid=125 cr=114 Jul 30 09:39:58 schopenhauer /kernel: i4b-L3-next_l3state: L3 FSM event [EV_SETUPRQ - L4 SETUP REQ]: [ST_U0 - Null => ST_SUSE - $ Jul 30 09:39:58 schopenhauer /kernel: i4b-L3-F_00A: FSM function F_00A executing Jul 30 09:39:58 schopenhauer /kernel: i4b-L2-i4b_dl_establish_req: unit 0 Jul 30 09:39:58 schopenhauer /kernel: i4b-L2-i4b_next_l2state: FSM event [EV_DLESTRQ]: [ST_TEI_ASGD/3 => ST_AW_EST/4] Jul 30 09:39:58 schopenhauer /kernel: i4b-L2-F_T01: FSM function F_T01 executing Jul 30 09:39:58 schopenhauer /kernel: i4b-L2-i4b_tx_sabme: tx SABME, tei = 65 Jul 30 09:39:58 schopenhauer /kernel: i4b-L1-ph_data_req: ISAC_TX_ACTIVE set Jul 30 09:39:58 schopenhauer /kernel: i4b-L2-i4b_T200_restart: unit 0 Jul 30 09:39:58 schopenhauer /kernel: i4b-L3-T303_start: cr = 114 Jul 30 09:39:58 schopenhauer /kernel: i4b-L1-isic_isac_irq: ista =0x10 Jul 30 09:39:58 schopenhauer /kernel: i4b-L1-isic_isac_irq: ista =0x80 Jul 30 09:39:58 schopenhauer /kernel: i4b-L2-i4b_rxd_u_frame: UA, sapi = 0, tei = 65 Jul 30 09:39:59 schopenhauer /kernel: i4b-L2-F_AE09: FSM function F_AE09 executing Jul 30 09:39:59 schopenhauer /kernel: i4b-L2-i4b_T200_stop: unit 0 Jul 30 09:39:59 schopenhauer /kernel: i4b-L2-i4b_next_l2state: FSM S-event [EV_RXUA]: [ST_AW_EST => ST_MULTIFR] Jul 30 09:39:59 schopenhauer /kernel: i4b-L2-i4b_next_l2state: FSM executing postfsmfunc! Jul 30 09:39:59 schopenhauer /kernel: i4b-L3-i4b_dl_establish_cnf: unit=0, index=0 cdid=125 cr=114 Jul 30 09:39:59 schopenhauer /kernel: i4b-L3-next_l3state: L3 FSM event [EV_DLESTCF - L2 DL_Est_Cnf]: [ST_OW - Out Wait EST => S$ Jul 30 09:39:59 schopenhauer /kernel: i4b-L3-F_DECF1: FSM function F_DECF1 executing Jul 30 09:39:59 schopenhauer /kernel: i4b-L3-i4b_l3_tx_setup: tx SETUP for cr 114 Jul 30 09:39:59 schopenhauer /kernel: i4b-L2-i4b_dl_data_req: unit 0 Jul 30 09:39:59 schopenhauer /kernel: i4b-L1-ph_data_req: ISAC_TX_ACTIVE set Jul 30 09:39:59 schopenhauer /kernel: i4b-L2-i4b_T200_start: unit 0 Jul 30 09:39:59 schopenhauer /kernel: i4b-L1-isic_isac_irq: ista =0x10 Jul 30 09:39:59 schopenhauer /kernel: i4b-L1-isic_isac_irq: ista =0x10 Jul 30 09:39:59 schopenhauer /kernel: i4b-L1-isic_isac_irq: ista =0x80 Jul 30 09:39:59 schopenhauer /kernel: i4b-L2-i4b_rxd_s_frame: rx'd RR, N(R) = 1 Jul 30 09:39:59 schopenhauer /kernel: i4b-L2-F_MF17: FSM function F_MF17 executing Jul 30 09:39:59 schopenhauer /kernel: i4b-L2-i4b_T200_stop: unit 0 Jul 30 09:39:59 schopenhauer /kernel: i4b-L2-i4b_next_l2state: FSM S-event [EV_RXRR]: [ST_MULTIFR => ST_MULTIFR] Jul 30 09:39:59 schopenhauer /kernel: i4b-L1-isic_isac_irq: ista =0x80 Jul 30 09:39:59 schopenhauer /kernel: i4b-L3-i4b_decode_q931: Call Ref, len 1, val 114, flag 1 Jul 30 09:39:59 schopenhauer /kernel: i4b-L4-cd_by_unitcr: found cd, index=0 cdid=125 cr=114 Jul 30 09:39:59 schopenhauer /kernel: i4b-L3-i4b_decode_q931_message: CALL_PROCEEDING message Jul 30 09:39:59 schopenhauer /kernel: i4b-L3-i4b_decode_q931_codeset0: IEI_CHANNELID - channel 0, exclusive = 1 Jul 30 09:39:59 schopenhauer /kernel: i4b-L3-next_l3state: L3 FSM event [EV_CALLPRC - rxd CALL PROC]: [ST_U1 - Out Init => ST_U3$ Jul 30 09:39:59 schopenhauer /kernel: i4b-L3-F_01M: FSM function F_01M executing Jul 30 09:39:59 schopenhauer /kernel: i4b-L3-T303_stop: cr = 114 Jul 30 09:39:59 schopenhauer /kernel: i4b-L3-T310_start: cr = 114 Jul 30 09:39:59 schopenhauer /kernel: i4b-L2-i4b_tx_rr_response: tx RR, unit = 0 Jul 30 09:39:59 schopenhauer /kernel: i4b-L1-ph_data_req: ISAC_TX_ACTIVE set Jul 30 09:39:59 schopenhauer /kernel: i4b-L2-i4b_T200_stop: unit 0 Jul 30 09:39:59 schopenhauer /kernel: i4b-L1-isic_isac_irq: ista =0x10 Jul 30 09:39:59 schopenhauer /kernel: i4b-L1-isic_isac_irq: ista =0x80 Jul 30 09:39:59 schopenhauer /kernel: i4b-L3-i4b_decode_q931: Call Ref, len 1, val 114, flag 1 Jul 30 09:39:59 schopenhauer /kernel: i4b-L4-cd_by_unitcr: found cd, index=0 cdid=125 cr=114 Jul 30 09:39:59 schopenhauer /kernel: i4b-L3-i4b_decode_q931_message: CONNECT message Jul 30 09:39:59 schopenhauer /kernel: i4b-L3-i4b_decode_q931_codeset0: IEI_DATETIME Jul 30 09:39:59 schopenhauer /kernel: i4b-L3-i4b_decode_q931_codeset0: IEI_CONCTDNO Jul 30 09:39:59 schopenhauer /kernel: i4b-L3-next_l3state: L3 FSM event [EV_CONNECT - rxd CONNECT]: [ST_U3 - Out Proc => ST_U10 $ Jul 30 09:39:59 schopenhauer /kernel: i4b-L3-F_03O: FSM function F_03O executing Jul 30 09:39:59 schopenhauer /kernel: i4b-L3-T310_stop: cr = 114 Jul 30 09:39:59 schopenhauer /kernel: i4b-L3-i4b_l3_tx_connect_ack: tx CONNECT ACK for cr 114 Jul 30 09:39:59 schopenhauer /kernel: i4b-L2-i4b_dl_data_req: unit 0 Jul 30 09:39:59 schopenhauer /kernel: i4b-L1-ph_data_req: ISAC_TX_ACTIVE set Jul 30 09:39:59 schopenhauer /kernel: i4b-L2-i4b_T200_start: unit 0 Jul 30 09:39:59 schopenhauer /kernel: i4b-L4-i4b_l4_connect_active_ind: last_active/connect_time=901784398 Jul 30 09:39:59 schopenhauer /kernel: i4b-L1-isic_bchannel_setup: unit=0, channel=0, activate Jul 30 09:40:00 schopenhauer /kernel: i4b-L4-i4b_l4_setup_timeout: 901784398: outgoing-call, start 55 sec nocheck window Jul 30 09:40:00 schopenhauer /kernel: i4b-L1-isic_isac_irq: ista =0x10 Jul 30 09:40:00 schopenhauer /kernel: i4b-L1-isic_isac_irq: ista =0x80 Jul 30 09:40:00 schopenhauer /kernel: i4b-L2-i4b_rxd_s_frame: rx'd RR, N(R) = 2 Jul 30 09:40:00 schopenhauer /kernel: i4b-L2-F_MF17: FSM function F_MF17 executing Jul 30 09:40:00 schopenhauer /kernel: i4b-L2-i4b_T200_stop: unit 0 Jul 30 09:40:00 schopenhauer /kernel: i4b-L2-i4b_next_l2state: FSM S-event [EV_RXRR]: [ST_MULTIFR => ST_MULTIFR] Jul 30 09:40:00 schopenhauer /kernel: isppp0: phase authenticate Jul 30 09:40:00 schopenhauer /kernel: isppp0: phase network Jul 30 09:40:00 schopenhauer /kernel: isppp0: phase terminate Jul 30 09:40:00 schopenhauer /kernel: isppp0: phase dead Regards, Marc. 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?199808010825.KAA17791>