[nsp] AS5300 modem dialout

Markus Wild mwild at vianetworks.ch
Mon Nov 10 10:42:49 EST 2003 

Hello,

we're having a somewhat odd problem with our AS5300.. We 
currently have 2 of these used to provide dial-in services
to our customers, and also use them successfully to perform
ISDN dial-out to other locations.

I've now tried to set them up to allow for modem dial-out
(primarily as a precondition to later on implement 
fax off-ramp services). I'm debugging this using reverse-telnet 
to one of the modems. I'm dialing out to a voice number, and I 
see the phone receiving a call (displays the number), but that
call hangs up immediately. After teaking just about any parameter
I could find I'm now pretty much at a loss to figure out what
could be the reason for this behavior. 

For test purposes, I hooked the PRI that used to go to the test
5300 to an Ascend/Lucent Max6000. With this router, I was able
to successfully use a modem to dial the same target number that
the 5300 hung up on immediately after call setup, so I'm fairly 
certain it's not the telco side that's causing the problems.

The 5300 are running 12.3(1a) IP-PLUS. They have MICA modems, but
no VOIP cards. The PRI switch-type is NET5.

I'm appending a bit of debugging output. Watch the immediate 
	Mica Modem(2/59): Link Terminate(0x2)
following
	CSM_PROC_OC5_WAIT_FOR_CARRIER: CSM_EVENT_ISDN_CALL_PROGRESSING at slot 2, port 59

Any ideas would be welcome...

This is after ATD041798XXXX

13:00:50.508: Mica Modem(2/59): Rcvd Dial String(041798XXXX)
13:00:50.508: Mica Modem(2/59): Dial String to be processed (041798XXXX)
13:00:50.508: Mica Modem(2/59): End of Dial String
13:00:50.508: CSM_PROC_IDLE: CSM_EVENT_MODEM_OFFHOOK at slot 2, port 59
13:00:50.508: csm_get_signaling_channel csm_call_info->bchan_num 0xFFFFFFFF
13:00:50.508: csm_get_signaling_channel dchan_index=25167,next_index=0,dchan_info=0x62D0ED78
13:00:50.508: CSM_PROC_OC3_COLLECT_ALL_DIGIT: CSM_EVENT_GET_ALL_DIGITS at slot 2, port 59
13:00:50.508: CSM_PROC_OC3_COLLECT_ALL_DIGIT: called party num: (041798XXXX) at slot 2, port 59
13:00:50.508: csm_get_signaling_channel csm_call_info->bchan_num 0xFFFFFFFF
13:00:50.508: csm_get_signaling_channel dchan_index=25167,next_index=0,dchan_info=0x62D0ED78
13:00:50.508: modem_check_dialout_controller (modem_info=0x624F7270), return value=TRUE
13:00:50.508: CSM_PROC_OC3_COLLECT_ALL_DIGIT:  csm_call_info->bchan_num 0xFFFFFFFF
13:00:50.508: ISDN Se0:15 EVENT: process_modem_command: received event VOICE_ISDNCALL on callid 0x801D and bchan -1 ces 0 cause 16 switch type 18
13:00:50.508: ISDN Se0:15 EVENTd: process_pri_call: call id 0x801D, number 041798XXXX, speed 64, call type VOICE, redial No, CSM call Yes, pdata No
13:00:50.508: ISDN Se0:15 EVENTd: fill_cid_table_voice: Don't know calling number for redial.
13:00:50.508: ISDN Se0:15 EVENTd: fill_cid_table_voice: Created entry call_id 0x801D, speed 64, remote 041798XXXX, calling 
13:00:50.508: ISDN Se0:15 EVENTd: pak_private_number: Packing Calling Pty. Num. without digits
13:00:50.512: ISDN Se0:15 EVENTd: pak_private_number: called type/plan overridden by call_decode
13:00:50.512: ISDN Se0:15 EVENTd: calltrkr_setup_received: isdn_info=1656252420l, call_id=0x801D ORIGINATE
13:00:50.512: ISDN Se0:15 EVENTd: calltrkr_setup_received: calltracker disabled
13:00:50.512: ISDN Se0:15 BACKHAUL: srl_send_l3_pak:
        source_id = Q.931, dest_id = Q.921, prim = DL_DATA_REQ
        priv_len = 4 int_id = 0x62B7E16C datasize = 44
13:00:50.512: ISDN Se0:15 BACKHAUL: data =  0x62B7E16C00000300024004E600010800
13:00:50.512:   0802001C0504038090A31803A9839A70
13:00:50.512:   0B81303431373938XXXXXXXX
13:00:50.516: ISDN Se0:15 **DEBUG**: L2_Mail: IQlen 0
13:00:50.516: ISDN Se0:15 Q931: TX -> SETUP pd = 8  callref = 0x001C 
        Bearer Capability i = 0x8090A3 
                Standard = CCITT 
                Transer Capability = Speech  
                Transfer Mode = Circuit 
                Transfer Rate = 64 kbit/s 
        Channel ID i = 0xA9839A 
                Exclusive, Channel 26 
        Called Party Number i = 0x81, '041798XXXX' 
                Plan:ISDN, Type:Unknown
13:00:50.744: ISDN Se0:15 Q931: RX <- CALL_PROC pd = 8  callref = 0x801C 
        Channel ID i = 0xA9839A 
                Exclusive, Channel 26
13:00:50.744: ISDN Se0:15 BACKHAUL: data =  0x62B7E16C000000000241046400010100
13:00:50.744:   0802801C021803A9839A
13:00:50.744: ISDN Se0:15 BACKHAUL: L3IF_rx_L2_pak: received data 0x0802801C021803A9839A
13:00:50.748: ISDN Se0:15 EVENT: process_rxstate: ces/callid 1/0x801D calltype 2 CALL_PROCEEDING
13:00:50.748: ISDN Se0:15 EVENTd: calltrkr_setup_received: isdn_info=1656740972l, call_id=0x801D ORIGINATE
13:00:50.748: EVENT_FROM_ISDN: dchan_idb=0x62B7E16C, call_id=0x801D, ces=0x1
   bchan=0x19, event=0x3, cause=0x0
13:00:50.748: EVENT_FROM_ISDN:(801D): DEV_CALL_PROC at slot 2 and port 59, bchan 25 on Serial0:15
13:00:50.748: CSM_PROC_OC4_DIALING: CSM_EVENT_ISDN_BCHAN_ASSIGNED at slot 2, port 59
13:00:50.748: csm_connect_pri_vdev: TS allocated at bp_stream 0, bp_Ch 27, vdev_common 0x624F74BC 2/59
13:00:50.748: Mica Modem(2/59): Configure(0x1 = 0x1) 
13:00:50.748: Mica Modem(2/59): Configure(0x23 = 0x0) 
13:00:50.748: Mica Modem(2/59): Call Setup
13:00:50.824: Mica Modem(2/59): State Transition to Call Setup
13:00:51.192: ISDN Se0:15 Q931: RX <- ALERTING pd = 8  callref = 0x801C 
        Progress Ind i = 0x8288 - In-band info or appropriate now available 
13:00:51.192: ISDN Se0:15 BACKHAUL: data =  0x62B7E16C00000000024104E600010100
13:00:51.196:   0802801C011E028288
13:00:51.196: ISDN Se0:15 BACKHAUL: L3IF_rx_L2_pak: received data 0x0802801C011E028288
13:00:51.196: ISDN Se0:15 EVENT: process_rxstate: ces/callid 1/0x801D calltype 2 CALL_PROGRESS
13:00:51.196: EVENT_FROM_ISDN: dchan_idb=0x62B7E16C, call_id=0x801D, ces=0x1
   bchan=0x19, event=0x5, cause=0x1
13:00:51.196: EVENT_FROM_ISDN:(801D): DEV_CALL_PROGRESSING at slot 2 and port 59
13:00:51.196: CSM_PROC_OC5_WAIT_FOR_CARRIER: CSM_EVENT_ISDN_CALL_PROGRESSING at slot 2, port 59
13:00:51.196: Mica Modem(2/59): Link Terminate(0x2)
13:00:51.196: ISDN Se0:15 EVENT: process_modem_command: received event VOICE_HANGUP on callid 0x801D and bchan 25 ces 1 cause 31 switch type 18
13:00:51.196: ISDN Se0:15 EVENTd: process_modem_command: call id 0x801D ces may have changed is now 1
13:00:51.200: ISDN Se0:15 EVENTd: process_disconnect: call id 0x801D, call type is VOICE, b_idb 0x62BF55D4, ces 1, cause Normal, unspecified(0x1F)
13:00:51.200: ISDN Se0:15 EVENTd: calltrkr_call_disconnected: isdn_info=0x62BFDC6C, call_id=0x801D
13:00:51.200: ISDN Se0:15 EVENTd: process_disconnect: Raw Release Message 0x4B0001801D0308019F0803809F81
13:00:51.200: ISDN Se0:15 BACKHAUL: srl_send_l3_pak:
        source_id = Q.931, dest_id = Q.921, prim = DL_DATA_REQ
        priv_len = 4 int_id = 0x62B7E16C datasize = 25
13:00:51.200: ISDN Se0:15 BACKHAUL: data =  0x62B7E16C000003000240046400010100
13:00:51.200:   0802001C450802809F
13:00:51.200: ISDN Se0:15 **DEBUG**: L2_Mail: IQlen 0
13:00:51.200: ISDN Se0:15 Q931: TX -> DISCONNECT pd = 8  callref = 0x001C 
        Cause i = 0x809F - Normal, unspecified
13:00:51.212: Mica Modem(2/59): State Transition to Terminating
13:00:51.228: Mica Modem(2/59): State Transition to Idle
13:00:51.228: Mica Modem(2/59): Went onhook
13:00:51.228: CSM_PROC_OC7_BUSY_ERROR: CSM_EVENT_MODEM_ONHOOK at slot 2, port 59
13:00:51.228: CSM: No BP Timeslot is allocated for slot 2 port 59
13:00:51.228: CSM(2/59): Enter csm_enter_idle_state
13:00:51.276: ISDN Se0:15 Q931: RX <- RELEASE pd = 8  callref = 0x801C 
        Displ13:00:51.276: ISDN Se0:15 BACKHAUL: data =  0x62B7E16C00000000024104E600010100
13:00:51.276:   0802801C4D280846522E20302E3030
13:00:51.276: ISDN Se0:15 BACKHAUL: L3IF_rx_L2_pak: received data 0x0802801C4D280846522E20302E3030
13:00:51.276: ISDN Se0:15 BACK = Q.931, dest_id = Q.921, prim = DL_DATA_REQ
        priv_len = 4 int_id = 0x62B7E16C datasize = 21
13:00:51.276: ISDN Se0:15 BACKHAUL: data =  0x62B7E16C00000300024004E600010800
13:00:51.276:   0802001C5A
13:00:51.276: ISDN Se0:15 EVENT: process_rxstatex801D calltype 2 CALL_CLEARED
13:00:51.276: ISDN Se0:15 EVENTd: calltrkr_call_cleared: isdn_info=0x62B86804, call_id=0x801D
13:00:51.280: ISDN Se0:15 EVENTd: calltrkr_call_cleared: isdn_info=0x62BFDC6C, call_id=0x801D
13:00:51.280: EVENT_FROM_ISDN: dchan_call_id=0x801D, ces=0x1
   bchan=0x19, event=0x0, cause=0x0
13:00:51.280: ISDN Se0:15 **DEBUG**: L2_Mail: IQlen 0
13:00:51.280: ISDN Se0:15 Q931: TX -> RELEASE_COMP pd = 8  callref = 0x001C
13:02:24.595: ISDN Se0:15 Q931: RX <- STATUS_ENQ pd = 8  callref Se0:15 BACKHAUL: data =  0x62B7E16C000000000241046400010100
13:02:24.595:   0802005875
13:02:24.595: ISDN Se0:15 BACKHAUL: L3IF_rx_L2_pak: received data 0x0802005875
13:02:24.599: ISDN Se0:15 BACKHAUL: srl_send_l3_pak:
        source_id = Q.931, dest_id =L_DATA_REQ
        priv_len = 4 int_id = 0x62B7E16C datasize = 28
13:02:24.599: ISDN Se0:15 BACKHAUL: data =  0x62B7E16C00000300024004E60001C021
13:02:24.599:   080280587D0802809E14010A
13:02:24.599: ISDN Se0:15 **DEBUG**: L2_Mail: IQlen 0
13:02:24.599: ISDN Se0:15 Q931: TX -> STATUS pd = 8  callref = 0x8058 
        Cause i = 0x809E - Response to STATUS ENQUIRY or number unassigned 
        Call State i = 0x0A
13:04:13.095: ISDN Se0:15 Q931: RX <- DISCONNECT pd = 8  callref = 0x0058 
        Cause i = 0x8090 - Normal call clearing


Modem(2/59) Operational-Status: 
 
 Parameter #0  Disconnect Reason Info:  (0x7F02)
       Type (=3 ):  Condition occurred during call setup
      Class (=31):  Requested by host
     Reason (=2 ):  dialed number didn't answer 

(well, the number _did_ answer according to the behavior of the
called phone, but the modem didn't realize this...).

Thanks for reading this far:)

Markus

More information about the cisco-nsp mailing list