Cisco IOS Voice Troubleshooting and Monitoring -- VoIP Network Troubleshooting Using Cisco VoIP Internal Error Codes
From DocWiki
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.
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.
