Cisco IOS Voice Troubleshooting and Monitoring -- VoIP Network Troubleshooting Using Cisco VoIP Internal Error Codes

From DocWiki

Revision as of 04:28, 5 March 2009 by Pzimmerm (Talk | contribs)
(diff) ← Older revision | Latest revision (diff) | Newer revision → (diff)
Jump to: navigation, search

IECs are generated for errors that cause the gateway to release or refuse a call. This section provides procedural and reference information used to troubleshoot gateway-detected errors and resolve problems on the gateway and with other VoIP network entities.

Because fields within the IEC identify which network entity and subsystem originated an error, they can be used to diagnose and isolate failures that can cause call disconnects.

Guide Contents
Troubleshooting Cisco IOS Voice Overview
Debug Command Output on Cisco IOS Voice Gateways
Filtering Troubleshooting Output
Cisco VoIP Internal Error Codes
Troubleshooting Cisco IOS Voice Telephony
Troubleshooting Cisco IOS Voice Protocols
Troubleshooting Cisco IOS Telephony Applications
Monitoring the Cisco IOS Voice Network
Cause Codes and Debug Values

Contents

Troubleshooting Two-Stage Dialing Failures

The following example shows how to troubleshoot a two-stage dialing failure.

Symptom

The Cisco router or gateway rejects a call placed by a PSTN ISDN user after all the digits have been dialed.

Problem Description

The PSTN user enters a destination number that is routed through the PSTN ISDN switch, which sends an ISDN SETUP message to the router. The router tags the incoming call leg and sends back an ISDN CONNECT message. The caller receives second dial tone. The router then enters the digit collection stage to use the collected digits to route the call to the next hop, at which point the router rejects the call.

Troubleshooting Tasks

Perform the following steps to determine the reason for call failure.

1. Use the voice iec syslog command to enable displaying of IECs as they are encountered in real-time.

2. Use the voice iec statistics type iec command to configure the collection of IEC statistics.

3. Use the show running-config command to verify IEC, ISDN, and dial-peer configuration, as shown in the following partial sample output:


 Router> show running-config
 Building configuration...  
 !  
 voice rtp send-recv  
 !  
 voice service voip   

The following lines show the IEC configuration:

  voice iec syslog   
 no voice hpi capture buffer  
 no voice hpi capture destination   
 voice statistics type iec 
 !  
 !  
 !  

The following lines show the T1 configuration:

 controller T1 0  
  framing esf  
  clock source line primary  
  linecode b8zs  
  cablelength short 133  
  pri-group timeslots 1-24  
 !  

The following lines show the ISDN configuration:

 interface Serial0:23  
  no ip address  
  no logging event link-status  
  isdn switch-type primary-ni  
  isdn incoming-voice modem  
  no cdp enable  
 !  

The following lines show the dial-peer configuration. Because the dial-peer voice 1 is not configured for direct inward dialing (DID), the inbound call leg is considered to be configured for two-stage dialing, and the router returns a second dial tone.

 dial-peer voice 1 pots  
  incoming called-number .  
  port 0:D  
 !  
 dial-peer voice 2 voip  
  destination-pattern 83101  
  session target ipv4:172.69.85.107  
  dtmf-relay h245-alphanumeric  
  codec g711ulaw  
  ip qos dscp cs5 media  
 !  
 !end  

4. Use the show controller t1 command to display T1 status. Verify that the T1 is UP and that there are no errors.

 Router> show controller t1 0  
 T1 0 is up. 
   Applique type is Channelized T1  
   Cablelength is short 133  
   No alarms detected.  
   alarm-trigger is not set  
   Version info of slot 0:  HW: 1, PLD Rev: 11  
   Framer Version: 0x8  
 !  
 !  
 !  
 Framing is ESF, Line Code is B8ZS, Clock Source is Line Primary.  
   Data in current interval (0 seconds elapsed):  
      0 Line Code Violations, 0 Path Code Violations  
      0 Slip Secs, 0 Fr Loss Secs, 0 Line Err Secs, 0 Degraded Mins  
      0 Errored Secs, 0 Bursty Err Secs, 0 Severely Err Secs, 0 Unavail Secs  

5. Use the show isdn status command to display ISDN status. Verify the ISDN Layer 2 status is MULTIPLE_FRAME_ESTABLISHED.

 Router> show isdn status  
 Global ISDN Switchtype = primary-ni  
 ISDN Serial0:23 interface  
         dsl 0, interface ISDN Switchtype = primary-ni  
     Layer 1 Status:  
         ACTIVE  
     Layer 2 Status:  
         TEI = 0, Ces = 1, SAPI = 0, State = MULTIPLE_FRAME_ESTABLISHED 
     Layer 3 Status:  
         0 Active Layer 3 Call(s)  
     Active dsl 0 CCBs = 0  
     The Free Channel Mask:  0x807FFFFF  
     Number of L2 Discards = 0, L2 Session ID = 3  
     Total Allocated ISDN CCBs = 0  

6. Use the show isdn service command to display the status of each ISDN channel. Verify that the channels are IDLE and IN-SERVICE.

 Router> show isdn service 
 PRI Channel Statistics:  
 ISDN Se0:23, Channel [1-24]  
   Configured Isdn Interface (dsl) 0  
    Channel State (0=Idle 1=Proposed 2=Busy 3=Reserved 4=Restart 5=Maint_Pend)  
     Channel :  1 2 3 4 5 6 7 8 9 0 1 2 3 4 5 6 7 8 9 0 1 2 3 4  
     State   :  0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 3   
    Service State (0=Inservice 1=Maint 2=Outofservice)  
     Channel :  1 2 3 4 5 6 7 8 9 0 1 2 3 4 5 6 7 8 9 0 1 2 3 4  
     State   :  0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 2   

7. Use the show dial-peer voice summary command to display voice dial peer information. Verify that Admin and Operation status are up and up.

 Router> show dial-peer voice summary
              AD                                    PRE PASS  
 TAG    TYPE  MIN  OPER PREFIX    DEST-PATTERN      FER THRU SESS-TARGET   PORT  
 1      pots  up   up                                0                      0:D  
 2      voip  up   up             83101              0  syst ipv4:172.69.85.107  

8. Use the debug isdn q931 command to display information about call setup and teardown of ISDN network connections. Use the debug vtsp dsp, debug vtsp session, and debug voip ccapi inout commands to get digit collection information, as shown in the following partial output.

 Router# debug isdn q931  
 Router# debug vtsp dsp  
 Router# debug vtsp session  
 Router# debug voip ccapi inout  
 Aug 18 23:56:20.125: ISDN Se0:23 Q931: RX <- SETUP pd = 8  callref = 0x0226   
         Bearer Capability i = 0x8090A2   
                 Standard = CCITT   
                 Transer Capability = Speech    
                 Transfer Mode = Circuit   
                 Transfer Rate = 64 kbit/s   
         Channel ID i = 0xA98381   
                 Exclusive, Channel 1   
         Calling Party Number i = 0x2181, '40855501124'   
                 Plan:ISDN, Type:National   
         Called Party Number i = 0x80, '83101'   
                 Plan:Unknown, Type:Unknown  
 Aug 18 23:56:20.133: VDEV_ALLOCATE: 1/1 is allocated  
 !  
 !  
 !  


The following lines show the digit collection process, starting with the digit 8:

 Aug 18 23:56:28.265: //6/65F920768011/VTSP:(0:D):0:112:4386/vtsp_dsm_digit_begin_cb: 
   Digit begin: 8  
 Aug 18 23:56:28.265: //6/xxxxxxxxxxxx/CCAPI/cc_api_call_digit_begin: (dstVdbPtr=0x0, 
   dstCallId=0xFFFFFFFF, srcCallId=0x6,  
 !  
 !  
 !  

The router collects the next digit, 3, followed by 1, 0 and 2:

 Aug 18 23:56:30.253: //6/65F920768011/VTSP:(0:D):0:112:4386/vtsp_dsm_digit_begin_cb: 
   Digit begin: 3  
 Aug 18 23:56:30.253: //6/xxxxxxxxxxxx/CCAPI/cc_api_call_digit_begin: (dstVdbPtr=0x0, 
   dstCallId=0xFFFFFFFF, srcCallId=0x6,  
     digit=3, digit_begin_flags=0x1, rtp_timestamp=0xFFFFFE70  
     rtp_expiration=0x0, dest_mask=0x1)  
 !  
 !  
 !  
 Aug 18 23:56:30.885: //6/65F920768011/VTSP:(0:D):0:112:4386/vtsp_dsm_digit_begin_cb: 
   Digit begin: 1  
 Aug 18 23:56:30.885: //6/xxxxxxxxxxxx/CCAPI/cc_api_call_digit_begin: (dstVdbPtr=0x0,
   dstCallId=0xFFFFFFFF, srcCallId=0x6,  
     digit=1, digit_begin_flags=0x1, rtp_timestamp=0xFFFFFE70  
     rtp_expiration=0x0, dest_mask=0x1)  
 !  
 !  
 !  
 Aug 18 23:56:31.913: //6/65F920768011/VTSP:(0:D):0:112:4386/vtsp_dsm_digit_begin_cb: 
   Digit begin: 0  
 Aug 18 23:56:31.913: //6/xxxxxxxxxxxx/CCAPI/cc_api_call_digit_begin: (dstVdbPtr=0x0,
   dstCallId=0xFFFFFFFF, srcCallId=0x6,  
     digit=0, digit_begin_flags=0x1, rtp_timestamp=0xFFFFFE70  
     rtp_expiration=0x0, dest_mask=0x1)  
 !  
 !  
 !  
 Aug 18 23:56:33.185: //6/65F920768011/VTSP:(0:D):0:112:4386/vtsp_dsm_digit_begin_cb: 
  Digit begin: 2  
 Aug 18 23:56:33.185: //6/xxxxxxxxxxxx/CCAPI/cc_api_call_digit_begin: (dstVdbPtr=0x0, 
  dstCallId=0xFFFFFFFF, srcCallId=0x6,  
     digit=2, digit_begin_flags=0x1, rtp_timestamp=0xFFFFFE70  
     rtp_expiration=0x0, dest_mask=0x1)  
 !  
 !  
 !  
 Aug 18 23:56:33.265: //6/65F920768011/VTSP:(0:D):0:112:4386/vtsp_report_digit_control: 
  digit reporting disabled  
 Aug 18 23:56:33.265: //6/65F920768011/DSM: 0:D):0:112:4386/
  dsp_stream_mgr_register_disposition: Ev: E_DSM_DSP_DTMF_DIGIT_BEGIN Disp: DSM_DISP_IGNORE  
 Aug 18 23:56:33.265: //6/65F920768011/DSM:0:D):0:112:4386/
  dsp_stream_mgr_register_disposition: Ev: E_DSM_DSP_DTMF_DIGIT Disp: DSM_DISP_IGNORE  
 Aug 18 23:56:33.269: //6/xxxxxxxxxxxx/CCAPI/cc_api_call_report_digits_done: 
   (vdbPtr=0x639DB450, callID=0x6, disp=0)  
 Aug 18 23:56:33.269: //6/65F920768011/VTSP:(0:D):0:112:4386/vtsp_get_digit_timeouts: 
 Inter digit = 10, Initial digit = 10  

Because the router does not have an outgoing dial peer with destination pattern 83102, the call fails and an IEC is generated.

 Aug 18 23:56:33.269: %VOICE_IEC-3-GW: AFSAPP: Internal Error (Digit collect failed):
  IEC=1.1.179.10.24.6 on callID 6 GUID=65F92076D10E11D7801100B0640E6622 

9. Use the show voice iec description command to display the IEC definition:

 Router> show voice iec description 1.1.179.10.24.6  
     IEC Version: 1  
     Entity:   
     Category: 179 (External communication Error)  
     Subsystem: 10 (AFSAPP)  
     Error: 24 (Digit collect failed)  
     Diagnostic Code: 6  

IEC field definitions pinpoint the problem. Category code 179 indicates an external communication error, and an error code 24 indicates digit collection failure. For more information on IEC field definitions, see the Internal Error Code Notation.

Troubleshooting Socket Failures

The following example, which describes a TCP session failure, shows how errors detected by the gateway can be used to troubleshoot other devices on the VoIP network.

Symptom

An inbound call from an IP phone to the H.323 gateway fails.

Problem Description

A call is initially routed to the gateway and fails when a TCP session to Cisco CallManager session target cannot be established. The router pings Cisco CallManager, sending a TCP synchronization packet and receiving an ICMP destination unreachable error. Cisco CallManager cannot be pinged because the Cisco CallManager IP address is incorrect. After the IP address for Cisco CallManager is corrected, a second call fails, due to a different socket error. The router tries to establish another TCP session and sends an H225 setup message but Cisco CallManager drops the connection.

Troubleshooting Tasks

Perform the following steps to determine the reasons for both call failures.

1. Use the voice iec syslog command to enable display of IECs as they are encountered in real-time.

2. Use the voice iec statistics type iec command to configure the collection of IEC statistics.

3. Use the show running-config command to verify IEC, ISDN, and dial-peer configuration, as shown in the following partial sample output:

 Router> show running-config  
 Building configuration...  
 Current configuration : 3466 bytes  
 !  

The following lines show the IEC configuration:

 voice service voip   
 !  
 voice iec syslog  
 no voice hpi capture buffer  
 no voice hpi capture destination   
 voice statistics type iec  
 !  
 !  

The following lines show the T1 configuration:

 controller T1 0  
  framing esf  
  clock source line primary  
  linecode b8zs  
  cablelength short 133  
  pri-group timeslots 1-24  
 !  

The following lines show the ISDN configuration:

 interface Serial0:23  
  no ip address  
  no logging event link-status  
  isdn switch-type primary-ni   
  isdn incoming-voice modem  
  no cdp enable  
 !  
 ivoice-port 0:D  
 !  

The following lines show the dial-peer configuration, including the destination gateway IP address of Cisco CallManager:

 dial-peer voice 1 pots  
  incoming called-number  
  direct-inward-dialed  
  port 0:D  
 !  
 dial-peer voice 2 voip  
  destination-pattern 83101  
  session target ipv4:10.1.1.1  
  dtmf-relay h245-alphanumeric  
  codec g711ulaw  
  ip qos dscp cs5 media  
 !  
 !  
 end  

4. Use the debug isdn q931 command to display information about call setup and teardown of ISDN network connections.

 Router# debug isdn q931  
 Aug 19 01:46:02.886: ISDN Se0:23 Q931: RX <- SETUP pd = 8  callref = 0x022D   
         Bearer Capability i = 0x8090A2   
                 Standard = CCITT   
                 Transer Capability = Speech    
                 Transfer Mode = Circuit   
                 Transfer Rate = 64 kbit/s   
         Channel ID i = 0xA98381   
                 Exclusive, Channel 1   
         Calling Party Number i = 0x2181, '4085550111'   
                 Plan:ISDN, Type:National   
         Called Party Number i = 0x80, '83101'   
                 Plan:Unknown, Type:Unknown  

The following lines show the IEC and specify a network problem.

 Aug 19 01:46:03.342: %VOICE_IEC-3-GW: H323: Internal Error (SETUP send sock fail): 
    IEC=1.1.186.5.83.0 on callID 14 GUID=B99ACE6ED11D11D7801500B0640E6622  
 Aug 19 01:46:03.350: ISDN Se0:23 Q931: TX -> CALL_PROC pd = 8  callref = 0x822D   
         Channel ID i = 0xA98381   
                 Exclusive, Channel 1  
 Aug 19 01:46:03.362: ISDN Se0:23 Q931: TX -> DISCONNECT pd = 8  callref = 0x822D   
         Cause i = 0x80A6 - Network out of order  
 Aug 19 01:46:03.374: ISDN Se0:23 Q931: RX <- RELEASE pd = 8  callref = 0x022D   
         Cause i = 0x82E4 - Invalid information element contents  
 Aug 19 01:46:03.374: ISDN Se0:23 Q931: TX -> RELEASE_COMP pd = 8  callref = 0x822D  

5. Use the following commands to further isolate the problem:

  • The show voice iec description command displays the IEC definition.
  • The debug ip tcp transaction command displays output for packets the router sends and receives.
  • The debug cch323 h225 command provides the trace of the state transition of the H.225 state machine based on the processed events.

The following partial sample outputs from each command help you to isolate the cause of the network out of order message:

In the following example, the IEC definition indicates a category code of 186, a signaling socket failure, and shows that an error occurred during the SETUP PDU operation. The explanation for the error code 83 states that this error can happen if the remote IP address is a reachable address for pinging but is not a valid H.323 endpoint.

 Router# show voice iec description 1.1.186.5.83.0 
     IEC Version: 1  
     Entity: 1  
     Category: 186  
     Subsystem: 5   
     Error: 83   
     Diagnostic Code: 0  

Because the IEC specifies a signaling socket failure as the reason for call failure, you should enable the following debug commands to get more information.

 Router# debug ip tcp transaction  
 TCP special event debugging is on  
 Router# debug cch323 h225 
 H225 State Machine tracing is enabled  
 Router# terminal monitor  
 % Console already monitors  
 Router#  
 Aug 19 01:46:28.746: ISDN Se0:23 Q931: RX <- SETUP pd = 8  callref = 0x022E   
         Bearer Capability i = 0x8090A2   
                 Standard = CCITT   
                 Transer Capability = Speech    
                 Transfer Mode = Circuit   
                 Transfer Rate = 64 kbit/s   
         Channel ID i = 0xA98381   
                 Exclusive, Channel 1   
         Calling Party Number i = 0x2181, '4085551090'   
                 Plan:ISDN, Type:National   
         Called Party Number i = 0x80, '83101'   
                 Plan:Unknown, Type:Unknown  
 Aug 19 01:46:29.198: TCB63D2DAC8 created  
 Aug 19 01:46:29.198: TCB63D2DAC8 setting property TCP_PID (8) 63A2C044  
 Aug 19 01:46:29.198: TCB63D2DAC8 setting property TCP_NO_DELAY (1) 63A2C048  
 Aug 19 01:46:29.198: TCB63D2DAC8 setting property TCP_TOS (11) 63A2C070  
 Aug 19 01:46:29.198: TCB63D2DAC8 setting property TCP_NONBLOCKING_WRITE (10) 63A2C0D0  
 Aug 19 01:46:29.198: TCB63D2DAC8 setting property TCP_NONBLOCKING_READ (14) 63A2C0D0  
 Aug 19 01:46:29.198: TCB63D2DAC8 setting property unknown (15) 63A2C0D0  
 Aug 19 01:46:29.198: TCB63D2DAC8 setting property TCP_NO_DELAY (1) 63A2C08C  
 Aug 19 01:46:29.198: TCB63D2DAC8 setting property TCP_ALWAYSPUSH (17) 63A2C08C  
 Aug 19 01:46:29.198: TCB63D2DAC8 bound to 172.16.13.16.11005  
 Aug 19 01:46:29.198: TCP: sending SYN, seq 3651477840, ack 0  
 Aug 19 01:46:29.198: TCP0: Connection to 10.1.1.1:1720, advertising MSS 536  
 Aug 19 01:46:29.198: TCP0: state was CLOSED -> SYNSENT [11005 -> 10.1.1.1(1720)]  

The following lines show the 10.1.1.1 CallManager address is unreachable as it is configured, and the network out of order IEC is generated:

 Aug 19 01:46:29.202: TCP0: ICMP destination unreachable received  
 !  
 !  
 !Aug 19 01:46:29.206: %VOICE_IEC-3-GW: H323: Internal Error (SETUP send sock fail): 
    IEC=1.1.186.5.83.0 on callID 16 GUID=C904C18BD11D11D7801600B0640E6622  
 Aug 19 01:46:29.206: TCB 0x63D2DAC8 destroyed  
 Aug 19 01:46:29.206: //16/C904C18B8016/H323/run_h225_sm: Received event 
   H225_EV_CONN_LOST while at state H225_IDLE  
 Aug 19 01:46:29.214: ISDN Se0:23 Q931: TX -> CALL_PROC pd = 8  callref = 0x822E   
         Channel ID i = 0xA98381   
                 Exclusive, Channel 1  
 Aug 19 01:46:29.218: //16/C904C18B8016/H323/run_h225_sm: Received event H225_EV_RELEASE 
  while at state H225_IDLE  
 Aug 19 01:46:29.218: //16/C904C18B8016/H323/cch323_h225_set_new_state: 
   Changing from H225_IDLE state to H225_IDLE state  
 Aug 19 01:46:29.226: ISDN Se0:23 Q931: TX -> DISCONNECT pd = 8  callref = 0x822E   
         Cause i = 0x80A6 - Network out of order  
 !  
 !  

6. Use the show ip route command to display static routes, then use the ping command to check network connectivity to the destination address 10.1.1.1 using the ping command.

 Router> show ip route 
 Codes: C - connected, S - static, R - RIP, M - mobile, B - BGP  
        D - EIGRP, EX - EIGRP external, O - OSPF, IA - OSPF inter area   
        N1 - OSPF NSSA external type 1, N2 - OSPF NSSA external type 2  
        E1 - OSPF external type 1, E2 - OSPF external type 2  
        i - IS-IS, su - IS-IS summary, L1 - IS-IS level-1, L2 - IS-IS level-2  
        ia - IS-IS inter area, * - candidate default, U - per-user static route  
        o - ODR, P - periodic downloaded static route  
 Gateway of last resort is 172.16.13.3 to network 0.0.0.0  
      172.16.0.0/27 is subnetted, 1 subnets  
 C       172.16.13.0 is directly connected, Ethernet0  
 S*   0.0.0.0/0 [1/0] via 172.16.13.3  

The following lines show that the reason for Cisco CallManager TCP session failure is the incorrect 10.1.1.1 IP address:

 Router# ping 10.1.1.1
 Type escape sequence to abort.  
 Sending 5, 100-byte ICMP Echos to 10.1.1.1, timeout is 2 seconds:  
 ..U.U  
 Success rate is 0 percent (0/5)  
 Router# ping 10.1.1.1
      

7. Configure the correct IP address for Cisco CallManager and verify the configuration using the show running-config command.

 Router# config term  
 Enter configuration commands, one per line.  End with CNTL/Z.  
 Router(config)# dial-peer voice 2 
 Router(config-dial-peer)# session target ipv4:172.31.85.107
 Router(config-dial-peer)# end
 Router# show running-config
 !  
 !  
 !  
 dial-peer voice 2 voip  
  destination-pattern 83101  
  session target ipv4:172.31.85.107  
  dtmf-relay h245-alphanumeric  
  codec g711ulaw  
  ip qos dscp cs5 media  

8. Use the show debug command to display call traces enabled during a second call attempt.

 Router# show debug  
 CSM Voice:  
   Voice Call Switching Module debugging is on  
 The following ISDN debugs are enabled on all DSLs:  
 debug isdn error is             ON.  
 debug isdn q931 is              ON.   (filter is OFF)  
 Router#  
 Aug 19 02:05:36.349: ISDN Se0:23 Q931: RX <- SETUP pd = 8  callref = 0x0237   
         Bearer Capability i = 0x8090A2   
                 Standard = CCITT   
                 Transer Capability = Speech    
                 Transfer Mode = Circuit   
                 Transfer Rate = 64 kbit/s   
         Channel ID i = 0xA98381   
                 Exclusive, Channel 1   
         Calling Party Number i = 0x2181, '4085550111'   
                 Plan:ISDN, Type:National   
         Called Party Number i = 0x80, '83101'   
                 Plan:Unknown, Type:Unknown  
 Aug 19 02:05:36.353: VDEV_ALLOCATE: 1/2 is allocated  
 Aug 19 02:05:36.353: csm_vtsp_init_tdm: vdev@ 0x6355AAF4, voice_vdev@ 0x6355AA80  
 Aug 19 02:05:36.353: csm_vtsp_init_tdm: dsprm_tdm_allocate: tdm slot 1, dspm 1, dsp 2,
  dsp_channel 1  
 Aug 19 02:05:36.353: csm_vtsp_init_tdm: dsprm_tdm_allocate: tdm stream 4, channel 3, 
  bank 2, bp_channel 1, bp_stream 255  
 Aug 19 02:05:36.357: VDEV_DEALLOCATE: slot 1, port 4 is deallocated  
 Aug 19 02:05:36.805: ISDN Se0:23 Q931: TX -> CALL_PROC pd = 8  callref = 0x8237   
         Channel ID i = 0xA98381   
                 Exclusive, Channel 1  


The second call attempt also fails, generating a different IEC:

 Aug 19 02:05:36.845: %VOICE_IEC-3-GW: H323: Internal Error (Socket error): IEC=1.1.186.5.7.6
   on callID 8 GUID=750AFC91D12011D7800600B0640E6622  
 Aug 19 02:05:36.865: ISDN Se0:23 Q931: TX -> DISCONNECT pd = 8  callref = 0x8237   
         Cause i = 0x80A6 - Network out of order  
 Aug 19 02:05:36.873: ISDN Se0:23 Q931: RX <- RELEASE pd = 8  callref = 0x0237   
         Cause i = 0x82E4 - Invalid information element contents  
 Aug 19 02:05:36.877: ISDN Se0:23 Q931: TX -> RELEASE_COMP pd = 8  callref = 0x8237  


The following lines show that the subsequent call failed due to a different socket error. However, in this instance sending a ping to the remote IP address is successful:

 Router> show voice iec description 1.1.186.5.7.6 
     IEC Version: 1  
     Entity: 1 (Gateway)  
     Category: 186 (Signaling socket failure)  
     Subsystem: 5 (H323)  
     Error: 7 (Socket error)  
     Diagnostic Code: 6  
 Router> ping 172.69.85.107  
 Type escape sequence to abort.  
 Sending 5, 100-byte ICMP Echos to 172.69.85.107, timeout is 2 seconds:  
 !!!!!  
 Success rate is 100 percent (5/5), round-trip min/avg/max = 1/1/4 ms  


Use the debug ip tcp transaction, show debug, and debug cch323 h225 commands again.

 Router# debug ip tcp transaction 
 TCP special event debugging is on  
 Router# show debug 
 CSM Voice:  
   Voice Call Switching Module debugging is on  
 TCP:  
   TCP special event debugging is on  
 The following ISDN debugs are enabled on all DSLs:  
 debug isdn error is             ON.  
 debug isdn q931 is              ON.   (filter is OFF)  
 Router# debug cch323 h225 
 H225 State Machine tracing is enabled  
 Router#  
 Aug 19 02:06:36.637: ISDN Se0:23 Q931: RX <- SETUP pd = 8  callref = 0x0238   
         Bearer Capability i = 0x8090A2   
                 Standard = CCITT   
                 Transer Capability = Speech    
                 Transfer Mode = Circuit   
                 Transfer Rate = 64 kbit/s   
         Channel ID i = 0xA98381   
                 Exclusive, Channel 1   
         Calling Party Number i = 0x2181, '4085550111'   
                 Plan:ISDN, Type:National   
         Called Party Number i = 0x80, '83101'   
                 Plan:Unknown, Type:Unknown  
 Aug 19 02:06:36.641: VDEV_ALLOCATE: 1/3 is allocated  
 Aug 19 02:06:36.641: csm_vtsp_init_tdm: vdev@ 0x6355B240, voice_vdev@ 0x6355B1CC  
 Aug 19 02:06:36.641: csm_vtsp_init_tdm: dsprm_tdm_allocate: tdm slot 1, dspm 1, dsp 3,
   dsp_channel 1  
 Aug 19 02:06:36.641: csm_vtsp_init_tdm: dsprm_tdm_allocate: tdm stream 4, channel 5, bank 2,
   bp_channel 2, bp_stream 255  
 Aug 19 02:06:36.645: VDEV_DEALLOCATE: slot 1, port 8 is deallocated  
 Aug 19 02:06:37.089: TCB63604218 created  
 Aug 19 02:06:37.089: TCB63604218 setting property TCP_PID (8) 632036B4  
 Aug 19 02:06:37.089: TCB63604218 setting property TCP_NO_DELAY (1) 632036B8  
 Aug 19 02:06:37.089: TCB63604218 setting property TCP_TOS (11) 632036E0  
 Aug 19 02:06:37.089: TCB63604218 setting property TCP_NONBLOCKING_WRITE (10) 63203740  
 Aug 19 02:06:37.089: TCB63604218 setting property TCP_NONBLOCKING_READ (14) 63203740  
 Aug 19 02:06:37.089: TCB63604218 setting property unknown (15) 63203740  
 Aug 19 02:06:37.089: TCB63604218 setting property TCP_NO_DELAY (1) 632036FC  
 Aug 19 02:06:37.089: TCB63604218 setting property TCP_ALWAYSPUSH (17) 632036FC  
 Aug 19 02:06:37.089: TCB63604218 bound to 172.16.13.16.11001  
 Aug 19 02:06:37.089: TCP: sending SYN, seq 1593750728, ack 0  
 Aug 19 02:06:37.093: TCP0: Connection to 172.31.85.107:1720, advertising MSS 536  
 Aug 19 02:06:37.093: TCP0: state was CLOSED -> SYNSENT [11001 -> 172.31.85.107(1720)]  
 Aug 19 02:06:37.093: TCP0: state was SYNSENT -> ESTAB [11001 -> 172.31.85.107(1720)]  
 Aug 19 02:06:37.093: TCP0: Connection to 172.31.85.107:1720, received MSS 1460, MSS is 536  
 Aug 19 02:06:37.093: //10/98FA43DC8007/H323/run_h225_sm: Received event H225_EV_SETUP 
   while at state H225_IDLE  
 Aug 19 02:06:37.093: //10/98FA43DC8007/H323/check_qos_and_send_setup: Setup ccb 0x635F80E8  
 Aug 19 02:06:37.093: //10/98FA43DC8007/H323/run_h225_sm: Received event H225_EV_FS_SETUP 
   while at state H225_IDLE  
 Aug 19 02:06:37.093: //10/98FA43DC8007/H323/idle_fsSetup_hdlr: Setup ccb 0x635F80E8  
 Aug 19 02:06:37.097: //10/98FA43DC8007/H323/generic_send_setup: sending calling IE  
 Aug 19 02:06:37.097: //10/98FA43DC8007/H323/generic_send_setup: ====== PI = 0  
 Aug 19 02:06:37.097: //10/98FA43DC8007/H323/generic_send_setup: Send infoXCap=128,
  infoXRate=157, rateMult=89  
 Aug 19 02:06:37.097: //10/98FA43DC8007/H323/generic_send_setup: src address = 172.16.13.16;
  dest address = 172.31.85.107  
 Aug 19 02:06:37.097: //10/98FA43DC8007/H323/cch323_h225_set_new_state: Changing from 
  H225_IDLE state to H225_REQ_FS_SETUP state  
 Aug 19 02:06:37.101: TCP0: FIN processed  

The following lines show that the router was able to initialize the TCP session to Cisco CallManager, and the session went into the established state. After the router sent an H225 SETUP message it received a TCP RESET message to tear down the TCP session, indicating Cisco CallManager dropped the connection.

 Aug 19 02:06:37.101: TCP0: state was ESTAB -> CLOSEWAIT [11001 -> 172.31.85.107(1720)]  
 Aug 19 02:06:37.101: TCP0: RST received, Closing connection  
 Aug 19 02:06:37.101: TCP0: state was CLOSEWAIT -> CLOSED [11001 -> 172.31.85.107(1720)]  
 Aug 19 02:06:37.105: ISDN Se0:23 Q931: TX -> CALL_PROC pd = 8  callref = 0x8238   
         Channel ID i = 0xA98381   
                 Exclusive, Channel 1  
 Aug 19 02:06:37.105: %VOICE_IEC-3-GW: H323: Internal Error (Socket error): IEC=1.1.186.5.7.6
  on callID 10 GUID=98FA43DCD12011D7800700B0640E6622  
 Aug 19 02:06:37.105: TCB 0x63604218 destroyed  
 Aug 19 02:06:37.105: //10/98FA43DC8007/H323/run_h225_sm: Received event H225_EV_CONN_LOST 
  while at state H225_REQ_FS_SETUP  
 Aug 19 02:06:37.113: //10/98FA43DC8007/H323/run_h225_sm: Received event H225_EV_RELEASE while
  at state H225_REQ_FS_SETUP  
 Aug 19 02:06:37.113: //10/98FA43DC8007/H323/cch323_h225_set_new_state: Changing from 
 H225_REQ_FS_SETUP state to H225_IDLE state  
 Aug 19 02:06:37.121: ISDN Se0:23 Q931: TX -> DISCONNECT pd = 8  callref = 0x8238   
         Cause i = 0x80A6 - Network out of order  
 Aug 19 02:06:37.133: ISDN Se0:23 Q931: RX <- RELEASE pd = 8  callref = 0x0238   
         Cause i = 0x82E4 - Invalid information element contents  
 Aug 19 02:06:37.137: ISDN Se0:23 Q931: TX -> RELEASE_COMP pd = 8  callref = 0x8238  

9. Verify Cisco CallManager setting for the H.323 gateway to determine if the H.225 session was rejected by Cisco CallManager because the wrong IP address was configured for the H.323 gateway. Configure the correct IP address for the H.323 gateway, 172.16.13.16. For more information on CallManager configuration and IP address configuration, see the Cisco Unified Communications Manager Administration Guide.

10. Use debug commands to verify that the next call completes, as shown in the following partial debug output:

 Aug 19 02:10:36.707: ISDN Se0:23 Q931: RX <- SETUP pd = 8  callref = 0x0239   
         Bearer Capability i = 0x8090A2   
                 Standard = CCITT   
                 Transer Capability = Speech    
                 Transfer Mode = Circuit   
                 Transfer Rate = 64 kbit/s   
         Channel ID i = 0xA98381   
                 Exclusive, Channel 1   
         Calling Party Number i = 0x2181, '4085550111'   
                 Plan:ISDN, Type:National   
         Called Party Number i = 0x80, '83101'   
                 Plan:Unknown, Type:Unknown  
 Aug 19 02:10:36.711: VDEV_ALLOCATE: 1/2 is allocated  
 Aug 19 02:10:36.711: csm_vtsp_init_tdm: vdev@ 0x6355B98C, voice_vdev@ 0x6355B918  
 Aug 19 02:10:36.711: csm_vtsp_init_tdm: dsprm_tdm_allocate: tdm slot 1, dspm 1, dsp 4,
  dsp_channel 1  
 Aug 19 02:10:36.711: csm_vtsp_init_tdm: dsprm_tdm_allocate: tdm stream 5, channel 1, bank 2,
  bp_channel 3, bp_stream 255  
 Aug 19 02:10:36.711: VDEV_DEALLOCATE: slot 1, port 12 is deallocated  
 Aug 19 02:10:37.155: TCB63604A4C created  
 Aug 19 02:10:37.159: TCP: sending SYN, seq 3088300316, ack 0  
 Aug 19 02:10:37.159: TCP0: Connection to 172.69.85.107:1720, advertising MSS 536  
 Aug 19 02:10:37.159: TCP0: state was CLOSED -> SYNSENT [11003 -> 172.69.85.107(1720)]  
 Aug 19 02:10:37.163: TCP0: state was SYNSENT -> ESTAB [11003 -> 172.69.85.107(1720)]  
 Aug 19 02:10:37.163: TCP0: Connection to 172.69.85.107:1720, received MSS 1460, MSS is 536  
 Aug 19 02:10:37.163: //12/281160848008/H323/run_h225_sm: Received event H225_EV_SETUP while at
  state H225_IDLE  
 Aug 19 02:10:37.163: //12/281160848008/H323/check_qos_and_send_setup: Setup ccb 0x635F80E8  
 !  
 !  
 !  
 Aug 19 02:10:37.171: ISDN Se0:23 Q931: TX -> CALL_PROC pd = 8  callref = 0x8239   
         Channel ID i = 0xA98381   
                 Exclusive, Channel 1  
 Aug 19 02:10:38.151: //-1/xxxxxxxxxxxx/H323/cch323_h225_receiver: Received msg of type 
  CALLPROCIND_CHOSEN  
 Aug 19 02:10:38.155: //12/281160848008/H323/callproc_ind: ====== PI = 0  
 Aug 19 02:10:38.155: //12/281160848008/H323/callproc_ind: Call Manager detected  
 Aug 19 02:10:38.155: //12/281160848008/H323/cch323_h225_receiver: CALLPROCIND_CHOSEN: src 
  address = 172.16.13.16; dest address = 172.69.85.107  
 Aug 19 02:10:38.155: //12/281160848008/H323/run_h225_sm: Received event 
 H225_EV_CALLPROC_IND while at state H225_REQ_FS_SETUP  
 Aug 19 02:10:41.347: TCP0: state was SYNSENT -> ESTAB [11004 -> 172.69.85.107(1778)]  
 Aug 19 02:10:41.347: TCP0: Connection to 172.69.85.107:1778, received MSS 1460, MSS is 536  
 Aug 19 02:10:41.699: //12/281160848008/H323/run_h225_sm: Received event H225_EV_H245_SUCCESS
  while at state H225_WAIT_FOR_H245  
 Aug 19 02:10:41.703: //12/281160848008/H323/cch323_h225_set_new_state: Changing from 
 H225_WAIT_FOR_H245 state to H225_ACTIVE state  
 Aug 19 02:10:41.703: //12/281160848008/H323/setup_cfm_notify: status = 4800261B  
 Aug 19 02:10:41.703: //12/281160848008/H323/generic_setup_cfm_notify: ====== PI = 0; 
 status = C800261B  

In the next lines, the call connects and two-way communication is established.

 Aug 19 02:10:41.711: ISDN Se0:23 Q931: TX -> CONNECT pd = 8  callref = 0x8239  
 Aug 19 02:10:41.719: ISDN Se0:23 Q931: RX <- CONNECT_ACK pd = 8  callref = 0x0239  

The following lines show that after a two-minute call, the IP phone user hangs up and the call is disconnected with normal call clearing:

 Aug 19 02:10:43.635: TCP0: RST received, Closing connection  
 Aug 19 02:10:43.635: TCP0: state was ESTAB -> CLOSED [11004 -> 172.69.85.107(1778)]  
 Aug 19 02:10:43.635: TCB 0x6361C070 destroyed  
 !  
 !  
 !  
 Aug 19 02:10:43.663: TCP0: sending FIN  
 Aug 19 02:10:43.663: TCP0: state was FINWAIT1 -> FINWAIT2 [11003 -> 172.69.85.107(1720)]  
 Aug 19 02:10:43.663: TCP0: FIN processed  
 Aug 19 02:10:43.663: TCP0: state was FINWAIT2 -> TIMEWAIT [11003 -> 172.69.85.107(1720)]  
 Aug 19 02:10:43.671: ISDN Se0:23 Q931: TX -> DISCONNECT pd = 8  callref = 0x8239   
         Cause i = 0x8090 - Normal call clearing  
 Aug 19 02:10:43.679: ISDN Se0:23 Q931: RX <- RELEASE pd = 8  callref = 0x0239  
 Aug 19 02:10:43.683: ISDN Se0:23 Q931: TX -> RELEASE_COMP pd = 8  callref = 0x8239  
 Router#  
 Router# undebug all
 All possible debugging has been turned off.

Rating: 5.0/5 (6 votes cast)

Personal tools