Understanding SCCP and Call Flow Debugging

This section describes the SCCP and H.323 messages during call setup and debugging problems related to call setup. Understanding call flow is very useful in troubleshooting call control-related problems.

SCCP to SCCP Call

Figure 16-2 shows a sample exchange of messages between two SCCP clients (IP phones) during call setup. The messages are self-explanatory. You can view the SCCP call control messages by turning on the debug ephone detail command.

Figure 16-2. SCCP to SCCP Call Setup Messages

Note

The output of debug ephone detail is quite verbose and shouldn't be turned on for a Cisco CME in a production environment with large call volumes. Doing so can degrade the router's performance considerably. You can turn on the debugs for specific phones by adding the mac-address option to the debug, thus limiting the debug output.

Examples 16-20 to 16-23 show the output of debug ephone detail for a call between ephone 1 and ephone 2 connected to a Cisco CME at various states. The directory numbers of ephone 1 and ephone 2 are 1001 and 1002, respectively. The call control messages are highlighted for ease of reading.

Example 16-20 shows ephone 1 going off-hook and dialing the extension number of ephone 2. When the phone goes off-hook, the display on the phone changes to reflect the phone's current status. Also, the Cisco CME router instructs the phone to play dial tone when the phone goes off-hook. Each number dialed by the phone is shown as a KeypadButtonMessage followed by the number dialed. When the first digit is dialed, Cisco CME signals the phone to stop playing dial tone.

Example 16-20. Ephone 1 Dialing Ephone 2

CME_HQ#debug ephone detail
*Jun 6 15:25:18.623: ephone-1[2]:OFFHOOK 
*Jun 6 15:25:18.623: SkinnyGetCallState for DN 1 chan 1 IDLE
*Jun 6 15:25:18.623: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
*Jun 6 15:25:18.623: ephone-1[2]:SIEZE on activeLine 0 activeChan 1
*Jun 6 15:25:18.623: SkinnyGetCallState for DN 1 chan 1 IDLE
*Jun 6 15:25:18.623: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
*Jun 6 15:25:18.623: ephone-1[2]:Sieze auto select line 1 chan 1
*Jun 6 15:25:18.623: ephone-1[2]:UpdateCallState DN 1 chan 1 state 2 calleddn -1
 chan 1
*Jun 6 15:25:18.623: ephone-1[2]:Binding ephone-1 to DN 1 chan 1 s2s:0
*Jun 6 15:25:18.623: Assign Call Ref 3 to DN 1 chan 1
*Jun 6 15:25:18.623: Skinny Call State change for DN 1 chan 1 SIEZE from IDLE
*Jun 6 15:25:18.623: ephone-(1) DN 1 chan 1 calledDn -1 chan 1 callingDn -1 chan
 1 0.0.0.0 port=0
*Jun 6 15:25:18.623: SkinnyUpdateCstate DN 1 chan 1 state 1
*Jun 6 15:25:18.623: SkinnyGetCallState for DN 1 chan 1 SIEZE
*Jun
*Jun 6 15:25:18.623: called DN -1 chan 1, calling DN -1 chan 1 phone 1 s2s:0
*Jun 6 15:25:18.623: ephone-1[2][SEP000DBDBEF372]:SkinnyUpdateCState line 1 chan
 1 DN 1
*Jun 6 15:25:18.623: ephone-1[2]:SetCallState line 1 DN 1 chan 1 ref 3 TsOffHook
*Jun 6 15:25:18.623: ephone-1[2]:ClearCallPrompt line 1 ref 3
*Jun 6 15:25:18.623: ephone-1[2]:SelectPhoneSoftKeys set 4 mask FFFF for line 1
 ref 3 
*Jun 6 15:25:18.623: SkinnyGetCallState for DN 1 chan 1 SIEZE
*Jun 6 15:25:18.623: called DN -1 chan 1, calling DN -1 chan 1 phone 1 s2s:0
*Jun 6 15:25:18.623: ephone-1[2]:SetLineLamp 1 to ON 
*Jun 6 15:25:18.623: SkinnyGetCallState for DN 1 chan 1 SIEZE
*Jun 6 15:25:18.623: called DN -1 chan 1, calling DN -1 chan 1 phone 1 s2s:0

*Jun 6 15:25:18.623: ephone-1[2]:Check Plar Number
*Jun 6 15:25:18.627: SetDnCodec DN 1 chan 1 codec 4:G711Ulaw64k vad 250 size 160
*Jun 6 15:25:18.627: DN 1 chan 1 Voice_Mode
*Jun 6 15:25:18.627: SkinnyGetCallState for DN 1 chan 1 SIEZE
*Jun 6 15:25:18.627: called DN -1 chan 1, calling DN -1 chan 1 phone 1 s2s:0
*Jun 6 15:25:18.627: dn_tone_control DN=1 chan 1 tonetype=33:DtInsideDialTone 
 onoff=1 pid=156 
!output omitted for brevity
*Jun 6 15:25:18.627: Skinny StartTone 33 sent on ephone socket [2] 
 DtInsideDialTone
*Jun 6 15:25:19.635: ephone-1[2]:KeypadButtonMessage 1 
!output omitted for brevity
*Jun 6 15:25:19.635: ephone-1[2]:Store ReDial digit: 1 
*Jun 6 15:25:19.635: ephone-1[2]:SkinnyTryCall to 1 instance 1 start at 0
 secondary 0
*Jun 6 15:25:19.635: dn_tone_control DN=1 chan 1 tonetype=0:DtSilence onoff=0 
 pid=156 
!output omitted for brevity
*Jun 6 15:25:20.391: ephone-1[2]:KeypadButtonMessage 0 
!output omitted for brevity
*Jun 6 15:25:20.391: ephone-1[2]:Store ReDial digit: 10 
*Jun 6 15:25:20.391: ephone-1[2]:SkinnyTryCall to 10 instance 1 start at 0
 secondary 0
*Jun 6 15:25:20.643: ephone-1[2]:KeypadButtonMessage 0 
!output omitted for brevity
*Jun 6 15:25:20.643: ephone-1[2]:Store ReDial digit: 100 
*Jun 6 15:25:20.643: ephone-1[2]:SkinnyTryCall to 100 instance 1 start at 0
 secondary 0
*Jun 6 15:25:20.895: ephone-1[2]:KeypadButtonMessage 2 
!output omitted for brevity
*Jun 6 15:25:20.895: ephone-1[2]:Store ReDial digit: 1002 

Example 16-21 shows the Cisco CME router trying to set up a call to the number dialed (1002). As soon as the matching destination is found, the calling phone (1001) is updated with the destination's caller ID details. The called phone (1002) is set to ringing mode and is also updated with the caller ID of the calling phone.

Example 16-21. Cisco CME Setting Up a Call to Ephone 2

CME_HQ#debug ephone detail
*Jun 6 15:25:20.895: ephone-1[2]:SkinnyTryCall to 1002 instance 1 start at 0 
 secondary 0 
SkinnyTryCall to 1002 instance 1 match DN 2
!output omitted for brevity
*Jun 6 15:25:20.895: Skinny Call State change for DN 1 chan 1 ALERTING from SIEZE
!output omitted for brevity
*Jun 6 15:25:20.895: ephone-1[2]:SetCallState line 1 DN 1 chan 1 ref 3 TsRingOut
*Jun 6 15:25:20.895: ephone-1[2]:DialedNumber: 1002 DN 1 line 1 ref 3
*Jun 6 15:25:20.895: ephone-1[2][SEP000DBDBEF372]:CallPrompt line 1 ref 3: Ring
 Out
*Jun 6 15:25:20.895: ephone-1[2]:SelectPhoneSoftKeys set 8 mask FFFF for line 1

 ref 3
*Jun 6 15:25:20.895: SkinnyGetCallState for DN 1 chan 1 ALERTING
*Jun 6 15:25:20.895: called DN 2 chan 1, calling DN -1 chan 1 phone 1 s2s:0
*Jun 6 15:25:20.895: ephone-1[2]:SetLineLamp 1 to ON
*Jun 6 15:25:20.895: SetCallInfo calling dn 1 chan 1 dn 1 chan 1
calling [1001] called [1002] calling name Alex Anders called name Bill Bryce
*Jun 6 15:25:20.895: SetCallInfo DN 1 chan 1 is not Skinny-to-Skinny
*Jun 6 15:25:20.895: SkinnyGetCallState for DN 1 chan 1 ALERTING
*Jun 6 15:25:20.895: called DN 2 chan 1, calling DN -1 chan 1 phone 1 s2s:0
*Jun 6 15:25:20.895: ephone-1[2]:DisplayCallInfo outgoing call
*Jun 6 15:25:20.895: ephone-1[2]:SkinnyTryCall to 1002 instance 1 start at 0
 secondary 0
SkinnyTryCall to 1002 instance 1 match DN 2
*Jun 6 15:25:20.895: ephone-1[2]:Call Info DN 1 line 1 ref 3 called 1002 calling
 1001 origcalled 1002 calltype 2 
*Jun 6 15:25:20.895: ephone-1[2]:Call Info for chan 1 
*Jun 6 15:25:20.895: ephone-1[2]:Original Called Name Bill Bryce 
*Jun 6 15:25:20.895: ephone-1[2]: Alex Anders calling 
*Jun 6 15:25:20.895: ephone-1[2]: Bill Bryce 
*Jun 6 15:25:20.899: SkinnyUpdateDnState by EFXS_PROCEEDING 
 for DN 1 chan 1 to state ALERTING 
!output omitted for brevity
*Jun 6 15:25:20.899: SetCallInfo calling dn 1 chan 1 dn 2 chan 1
calling [1001] called [1002] calling name Alex Anders
!output omitted for brevity
*Jun 6 15:25:20.899: SkinnyUpdateDnState by EFXS_RING_GENERATE 
 for DN 2 chan 1 to state RINGING 
!output omitted for brevity
*Jun 6 15:25:20.903: DN 2 chan 1 ephone-2 state set to 4
*Jun 6 15:25:20.903: ephone-2[1]:SetCallState line 1 DN 2 chan 1 ref 4 TsRingIn
*Jun 6 15:25:20.903: ephone-2[1][SEP000B5FF93258]:CallPrompt line 1 ref 4: : 1001
*Jun 6 15:25:20.903: ephone-2[1]:SelectPhoneSoftKeys set 3 mask FFFF for line 1
 ref 4
*Jun 6 15:25:20.903: SkinnyGetCallState for DN 2 chan 1 RINGING
*Jun 6 15:25:20.903: called DN -1 chan 1, calling DN 1 chan 1 phone -1 incoming
 s2s:1
*Jun 6 15:25:20.903: ephone-2[1]:DisplayCallInfo incoming call 
*Jun 6 15:25:20.903: ephone-2[1]:SkinnyTryCall to 1002 instance 1 start at 0
 secondary 0
SkinnyTryCall to 1002 instance 1 match DN 2
*Jun 6 15:25:20.903: ephone-2[1]:Call Info DN 2 line 1 ref 4 called 1002 calling
 1001 origcalled 1002 calltype 1
*Jun 6 15:25:20.903: ephone-2[1]:Call Info for chan 1 
*Jun 6 15:25:20.903: ephone-2[1]:Original Called Name Bill Bryce 
*Jun 6 15:25:20.903: ephone-2[1]: Alex Anders calling 
*Jun 6 15:25:20.903: ephone-2[1]: Bill Bryce 
*Jun 6 15:25:20.903: ephone-2[1]:Internal RINGING 
*Jun 6 15:25:20.903: ephone-2[1]:Ringer Inside Ring On 
*Jun 6 15:25:20.903: SkinnyGetCallState for DN 2 chan 1 RINGING 
*Jun 6 15:25:20.903: called DN -1 chan 1, calling DN 1 chan 1 phone -1 incoming
 s2s:1
*Jun 6 15:25:20.903: ephone-2[1]:SetLineLamp 1 to BLINK 

Example 16-22 shows phone 2 answering the call. When it does so, the Cisco CME router sends an "Open Receive Channel" message to both the phones, specifying the codec and packet size. The phones acknowledge this message by sending an "Open Receive Channel Ack" message specifying the port number to start the media transmission. You can see that ephone 1 and ephone 2 send the "Open Receive Channel Ack" message specifying the port numbers 30148 and 29062, respectively. As soon as Cisco CME knows the port numbers for both the phones, a "StartMedia" message is sent to the phones, specifying the port numbers of the other phones to send media to. At this point, the phones start sending media to each other.

Example 16-22. Establishing Media

CME_HQ#debug ephone detail
*Jun 6 15:25:23.423: ephone-2[1]:OFFHOOK 
*Jun 6 15:25:23.423: ephone-2[1]:Disable Ringer line 1 
*Jun 6 15:25:23.423: ephone-2[1]:STOP RINGING 
*Jun 6 15:25:23.423: ephone-2[1]:Ringer Off 
*Jun 6 15:25:23.423: SkinnyGetCallState for DN 2 chan 1 RINGING
*Jun 6 15:25:23.423: called DN -1 chan 1, calling DN 1 chan 1 phone -1 incoming
 s2s:1
*Jun 6 15:25:23.423: ephone-2[1][SEP000B5FF93258]:Auto select answer line 1 dn -1
 chan 1
*Jun 6 15:25:23.423: ephone-2[1]:ANSWER call
*Jun 6 15:25:23.423: Calling DN 1 chan 1 from Called DN 2 chan 1 explicit
*Jun 6 15:25:23.423: SkinnyGetCallState for DN 1 chan 1 ALERTING
*Jun 6 15:25:23.423: called DN 2 chan 1, calling DN -1 chan 1 phone 1 s2s:0
*Jun 6 15:25:23.423: ephone-1[2][SEP000DBDBEF372]:Calling ephone-1 is bound to
 Calling DN 1 chan 1
*Jun 6 15:25:23.423: ephone-2[1][SEP000B5FF93258]:Answer Incoming call from
 ephone-(1) DN 1 chan 1
!output omitted for brevity
*Jun 6 15:25:23.423: Skinny Call State change for DN 2 chan 1 CONNECTED from RINGING
!output omitted for brevity
*Jun 6 15:25:23.423: ephone-2[1]:SelectPhoneSoftKeys set 1 mask FFDF for line 1
 ref 4
*Jun 6 15:25:23.423: SkinnyGetCallState for DN 2 chan 1 CONNECTED
*Jun 6 15:25:23.423: called DN -1 chan 1, calling DN 1 chan 1 phone 2 incoming
 s2s:1
*Jun 6 15:25:23.423: ephone-2[1]:SetLineLamp 1 to ON 
!output omitted for brevity
*Jun 6 15:25:23.423: ephone-1[2]:SelectPhoneSoftKeys set 1 mask FFDF for line 1
 ref 3
!output omitted for brevity
*Jun 6 15:25:23.427: ephone-2[1]:SkinnyTryCall to 1002 instance 1 start at 0
 secondary 0
SkinnyTryCall to 1002 instance 1 match DN 2
*Jun 6 15:25:23.427: ephone-2[1]:Call Info DN 2 line 1 ref 4 called 1002 calling
 1001 origcalled 1002 calltype 1
*Jun 6 15:25:23.427: ephone-2[1]:Call Info for chan 1
*Jun 6 15:25:23.427: ephone-2[1]:Original Called Name Bill Bryce
*Jun 6 15:25:23.427: ephone-2[1]: Alex Anders calling
*Jun 6 15:25:23.427: ephone-2[1]: Bill Bryce
*Jun 6 15:25:23.427: ephone-2[1]:Discard duplicate DisplayCallInfo for ref 4

*Jun 6 15:25:23.427: ephone-1[2]:OpenReceive DN 1 chan 1 codec 4:G711Ulaw64k 
 duration 20 ms bytes 160 
*Jun 6 15:25:23.427: ephone-2[1]:OpenReceive DN 2 chan 1 codec 4:G711Ulaw64k 
 duration 20 ms bytes 160 
!output omitted for brevity
*Jun 6 15:25:23.431: ephone-1[2]:Tone Off ignored - already sent
*Jun 6 15:25:23.431: dn_support_g729 true DN 1 chan 1 ephone-1
*Jun 6 15:25:23.431: dn_support_g723 false DN 1 chan 1 ephone-1
*Jun 6 15:25:23.431: dn_support_g729 true DN 2 chan 1 ephone-2
*Jun 6 15:25:23.431: dn_support_g723 false DN 2 chan 1 ephone-2
*Jun 6 15:25:23.431: DN 1 chan 1 End Voice_Mode
*Jun 6 15:25:23.431: SetDnCodec clear_defer media start
*Jun 6 15:25:23.431: SetDnCodec DN 1 chan 1 codec 4:G711Ulaw64k vad 0 size 160
*Jun 6 15:25:23.431: Skinny clear media defer_start
*Jun 6 15:25:23.431: DN 1 chan 1 Voice_Mode
*Jun 6 15:25:23.431: SkinnyGetCallState for DN 1 chan 1 CONNECTED
*Jun 6 15:25:23.431: called DN 2 chan 1, calling DN -1 chan 1 phone 1 s2s:1
*Jun 6 15:25:23.431: SkinnyUpdateDnState by MSG_RX_VOICE_MODE
 for DN 1 chan 1 to state CALL_START
!output omitted for brevity
*Jun 6 15:25:23.431: ephone-1[2]:Call Start ignored - mediaActive set
*Jun 6 15:25:23.431: SkinnyUpdateDnState by EFXS_OPEN_VOICE_PATH
 for DN 1 chan 1 to state CALL_START
*Jun 6 15:25:23.431: ephone-1[2]:UpdateCallState DN 1 chan 1 state 12 calleddn 2
 chan 1
*Jun 6 15:25:23.431: ephone-1[2]:Binding ephone-1 to DN 1 chan 1 s2s:1
*Jun 6 15:25:23.431: Binding calledDn 2 chan 1 to DN 1 chan 1
*Jun 6 15:25:23.431: ephone-1[2]:Call Start ignored - mediaActive set
*Jun 6 15:25:23.431: SetDnCodec DN 2 chan 1 codec 4:G711Ulaw64k vad 0 size 160
*Jun 6 15:25:23.431: DN 2 chan 1 Voice_Mode
*Jun 6 15:25:23.431: SkinnyGetCallState for DN 2 chan 1 CONNECTED
*Jun 6 15:25:23.431: called DN -1 chan 1, calling DN 1 chan 1 phone 2 incoming
 s2s:1
*Jun 6 15:25:23.431: SkinnyUpdateDnState by MSG_RX_VOICE_MODE
for DN 2 chan 1 to state CALL_START
*Jun 6 15:25:23.431: ephone-2[1]:UpdateCallState DN 2 chan 1 state 12 calleddn -1
 chan 1
*Jun 6 15:25:23.431: ephone-2[1]:Binding ephone-2 to DN 2 chan 1 s2s:1
*Jun 6 15:25:23.431: ephone-2[1]:Call Start ignored - mediaActive set
*Jun 6 15:25:23.431: SkinnyUpdateDnState by EFXS_OPEN_VOICE_PATH
 for DN 2 chan 1 to state CALL_START
*Jun 6 15:25:23.431: ephone-2[1]:UpdateCallState DN 2 chan 1 state 12 calleddn -1
 chan 1
*Jun 6 15:25:23.431: ephone-2[1]:Binding ephone-2 to DN 2 chan 1 s2s:1
*Jun 6 15:25:23.431: ephone-2[1]:Call Start ignored - mediaActive set
*Jun 6 15:25:23.435: SkinnyGetCallState for DN 1 chan 1 CONNECTED
*Jun 6 15:25:23.435: called DN 2 chan 1, calling DN -1 chan 1 phone 1 s2s:1
*Jun 6 15:25:23.435: SkinnyGetCallState for DN 1 chan 1 CONNECTED
*Jun 6 15:25:23.435: called DN 2 chan 1, calling DN -1 chan 1 phone 1 s2s:1
*Jun 6 15:25:23.435: dn_callerid_update DN 1 number= 1002 name= Bill Bryce in
 state CONNECTED

*Jun 6 15:25:23.435: dn_callerid_update (outgoing) DN 1 info updated to 
*Jun 6 15:25:23.435: calling= 1001 called= 1002 origCalled= 
*Jun 6 15:25:23.435: callingName= Alex Anders, calledName= Bill Bryce, 
 redirectedTo = 
*Jun 6 15:25:23.435: ephone-1[2][SEP000DBDBEF372]:refreshDisplayLine for line 1
 DN 1 chan 1
*Jun 6 15:25:23.435: SkinnyGetCallState for DN 2 chan 1 CONNECTED
*Jun 6 15:25:23.435: called DN -1 chan 1, calling DN 1 chan 1 phone 2 incoming
 s2s:1
*Jun 6 15:25:23.435: dn_callerid_update DN 2 number= 6502811001 name= Alex Anders
 in state CONNECTED
*Jun 6 15:25:23.435: dn_callerid_update (incoming) DN 2 info updated to
*Jun 6 15:25:23.435: calling= 1001 called= 1002 origCalled=
*Jun 6 15:25:23.435: callingName= Alex Anders, calledName= , redirectedTo =
*Jun 6 15:25:23.435: ephone-2[1][SEP000B5FF93258]:refreshDisplayLine for line 1
 DN 2 chan 1
*Jun 6 15:25:23.435: ephone-2[1]:OpenReceiveChannelAck:IP 10.1.1.102, port=30148,
 dn_index=2, dn=2, chan=1 
*Jun 6 15:25:23.435: Calling DN 1 chan 1 from Called DN 2 chan 1 explicit
*Jun 6 15:25:23.435: ephone-1[2][SEP000DBDBEF372]:Calling ephone-1 is bound to
 Calling DN 1 chan 1
*Jun 6 15:25:23.435: ephone-2[1]:Incoming called DN 2 chan 1 Far-ephone-1 calling
 DN 1 chan 1
*Jun 6 15:25:23.435: SkinnyGetCallState for DN 2 chan 1 CONNECTED
*Jun 6 15:25:23.435: called DN -1 chan 1, calling DN 1 chan 1 phone 2 incoming
 s2s:1
*Jun 6 15:25:23.435: ephone-2[1][SEP000B5FF93258]:s2s=1 DN:2 chan 1
*Jun 6 15:25:23.435: SkinnyGetCallState for DN 1 chan 1 CONNECTED
*Jun 6 15:25:23.435: called DN 2 chan 1, calling DN -1 chan 1 phone 1 s2s:1
*Jun 6 15:25:23.435: ephone-1[2]:StartMedia 10.1.1.102 port=30148 
*Jun 6 15:25:23.435: DN 1 chan 1 codec 4:G711Ulaw64k duration 20 ms bytes 160
*Jun 6 15:25:23.687: ephone-1[2]:OpenReceiveChannelAck:IP 10.1.1.101, port=29062,
 dn_index=1, dn=1, chan=1 
*Jun 6 15:25:23.687: ephone-1[2]:Outgoing calling DN 1 chan 1 Far-ephone-2 called
 DN 2 chan 1
*Jun 6 15:25:23.687: SkinnyGetCallState for DN 1 chan 1 CONNECTED
*Jun 6 15:25:23.687: called DN 2 chan 1, calling DN -1 chan 1 phone 1 s2s:1
*Jun 6 15:25:23.687: ephone-1[2][SEP000DBDBEF372]:s2s=1 DN:1 chan 1
*Jun 6 15:25:23.687: SkinnyGetCallState for DN 2 chan 1 CONNECTED
*Jun 6 15:25:23.687: called DN -1 chan 1, calling DN 1 chan 1 phone 2 incoming
 s2s:1
*Jun 6 15:25:23.687: ephone-2[1]:StartMedia 10.1.1.101 port=29062 
*Jun 6 15:25:23.687: DN 1 chan 1 codec 4:G711Ulaw64k duration 20 ms bytes 160
*Jun 6 15:25:23.939: ephone-1[2]:Refresh Display for line 1 chan 1
*Jun 6 15:25:23.939: SkinnyGetCallState for DN 1 chan 1 CONNECTED
*Jun 6 15:25:23.939: called DN 2 chan 1, calling DN -1 chan 1 phone 1 s2s:1
*Jun 6 15:25:23.939: ephone-1[2]:DisplayCallInfo outgoing call
*Jun 6 15:25:23.939: ephone-1[2]:SkinnyTryCall to 1002 instance 1 start at 0
 secondary 0
SkinnyTryCall to 1002 instance 1 match DN 2
*Jun 6 15:25:23.939: ephone-1[2]:Call Info DN 1 line 1 ref 3 called 1002 calling

 1001 origcalled 1002 calltype 2
*Jun 6 15:25:23.939: ephone-1[2]:Call Info for chan 1
*Jun 6 15:25:23.939: ephone-1[2]:Original Called Name Bill Bryce
*Jun 6 15:25:23.939: ephone-1[2]: Alex Anders calling
*Jun 6 15:25:23.939: ephone-1[2]: Bill Bryce
*Jun 6 15:25:23.939: ephone-2[1]:Refresh Display for line 1 chan 1
*Jun 6 15:25:23.939: SkinnyGetCallState for DN 2 chan 1 CONNECTED
*Jun 6 15:25:23.939: called DN -1 chan 1, calling DN 1 chan 1 phone 2 incoming
 s2s:1
*Jun 6 15:25:23.939: ephone-2[1]:DisplayCallInfo incoming call
*Jun 6 15:25:23.939: ephone-2[1]:SkinnyTryCall to 1002 instance 1 start at 0
 secondary 0
SkinnyTryCall to 1002 instance 1 match DN 2
*Jun 6 15:25:23.939: ephone-2[1]:Call Info DN 2 line 1 ref 4 called 1002 calling
 1001 origcalled 1002 calltype 1
*Jun 6 15:25:23.939: ephone-2[1]:Call Info for chan 1
*Jun 6 15:25:23.939: ephone-2[1]:Original Called Name Bill Bryce
*Jun 6 15:25:23.939: ephone-2[1]: Alex Anders calling
*Jun 6 15:25:23.939: ephone-2[1]: Bill Bryce

Example 16-23 shows the call clearing. Phone 2 disconnects the call by going on-hook. Cisco CME sends the other phone a "Close Receive" message followed by a "Stop Media" message to both the phones. This tears down the media path between the two phones. Also, an on-hook message is sent to phone 1.

Example 16-23. Call Clearing

CME_HQ#debug ephone detail
*Jun 6 15:25:29.231: ephone-2[1]:ONHOOK (from phone msgID=7) 
!output omitted for brevity
*Jun 6 15:25:29.231: called DN 2 chan 1, calling DN -1 chan 1 phone 1 s2s:1
*Jun 6 15:25:29.231: ephone-1[2]:CloseReceive 
*Jun 6 15:25:29.231: ephone-1[2]:StopMedia 
*Jun 6 15:25:29.231: ephone-2[1]:call clean up this DN 2 chan 1 was called by
 other DN 1 chan 1
*Jun 6 15:25:29.231: this ephone-2 other ephone-(1) other DN state CONNECTED
*Jun 6 15:25:29.231: ephone-2[1]:CloseReceive 
*Jun 6 15:25:29.231: ephone-2[1]:StopMedia 
*Jun 6 15:25:29.231: UpdateCallState DN 2 chan 1 state 0 phone-ref -1 calleddn
 -1 calleddn_chan 1
*Jun 6 15:25:29.231: DN 2 chan 1 End Voice_Mode
*Jun 6 15:25:29.231: Reset called DN binding for DN 1 (was 2)
*Jun 6 15:25:29.231: SetCallInfo calling dn -1 chan 1 dn 2 chan 1
calling [] called []
!output omitted for brevity
*Jun 6 15:25:29.231: ephone-2[1]:SelectPhoneSoftKeys set 0 mask FFBE for line 1
 ref 4
*Jun 6 15:25:29.231: SkinnyGetCallState for DN 2 chan 1 IDLE
*Jun 6 15:25:29.231: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
*Jun 6 15:25:29.231: ephone-2[1]:Clean Up Speakerphone state
*Jun 6 15:25:29.231: ephone-2[1]:SpeakerPhoneOnHook 
*Jun 6 15:25:29.231: ephone-2[1]:Clean up activeline 1
*Jun 6 15:25:29.231: ephone-2[1]:is_auto_local 0 for DN -1
*Jun 6 15:25:29.231: ephone-2[1]:Tone Off ignored - already sent
*Jun 6 15:25:29.235: SkinnyGetCallState for DN 2 chan 1 IDLE
*Jun 6 15:25:29.235: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
*Jun 6 15:25:29.235: ephone-2[1]:SetLineLamp 1 to OFF 
!output omitted for brevity
*Jun 6 15:25:29.235: ephone-1[2]:ClearCallPrompt line 1 ref 3
*Jun 6 15:25:29.235: ephone-1[2]:SelectPhoneSoftKeys set 0 mask FFBF for line 1
 ref 3
*Jun 6 15:25:29.235: SkinnyGetCallState for DN 1 chan 1 IDLE
*Jun 6 15:25:29.235: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
*Jun 6 15:25:29.235: ephone-1[2]:Clean Up Speakerphone state
*Jun 6 15:25:29.235: ephone-1[2]:SpeakerPhoneOnHook 
*Jun 6 15:25:29.235: ephone-1[2]:Clean up activeline 1
*Jun 6 15:25:29.235: ephone-1[2]:is_auto_local 0 for DN -1
*Jun 6 15:25:29.235: ephone-1[2]:Tone Off ignored - already sent
*Jun 6 15:25:29.235: ephone-1[2]:Clean Up phone offhook state
*Jun 6 15:25:29.235: SkinnyGetCallState for DN 1 chan 1 IDLE
*Jun 6 15:25:29.235: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
*Jun 6 15:25:29.235: ephone-1[2]:SetLineLamp 1 to OFF 
*Jun 6 15:25:29.235: UnBinding ephone-1 from DN 1 chan 1
*Jun 6 15:25:29.235: ephone-1[2]:SkinnyArmPhoneCallbacks scan 6 lines
*Jun 6 15:25:29.235: ephone-1[2]:SkinnyArmPhoneCallbacks for 1 targets
*Jun 6 15:25:29.235: ephone-1[2][SEP000DBDBEF372]:CallPrompt line 0 ref 0: Cisco
 CME Head Quarters
*Jun 6 15:25:29.235: ephone-1[2]:SkinnyCheckPendingCallBackPhone scan 6 lines
*Jun 6 15:25:29.235: ephone-2[1]:Far-end cleanup skiping ephone-1 DN 1 chan 1
 non-active line 0
*Jun 6 15:25:29.239: SkinnyGetCallState for DN 2 chan 1 IDLE
*Jun 6 15:25:29.239: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
*Jun 6 15:25:29.239: ephone-2[1]:SpeakerPhoneOnHook
*Jun 6 15:25:29.239: ephone-2[1]:ClearCallPrompt line 0 ref 0
*Jun 6 15:25:29.239: ephone-2[1]:SelectPhoneSoftKeys set 0 mask FFBE for line 0 ref 0
*Jun 6 15:25:29.239: ephone-2[1]:SkinnyArmPhoneCallbacks scan 2 lines
*Jun 6 15:25:29.239: ephone-2[1]:SkinnyArmPhoneCallbacks for 1 targets
*Jun 6 15:25:29.239: ephone-2[1][SEP000B5FF93258]:CallPrompt line 0 ref 0: Cisco
 CME Head Quarters
*Jun 6 15:25:29.239: ephone-2[1]:SkinnyCheckPendingCallBackPhone scan 2 lines

The highlighted output shown in Examples 16-20 to 16-23 points out the key messages to look for when troubleshooting call flow issues. For example, if the problem is no dial tone when the phone goes off-hook, you should look for the "StartTone" message (shown in Example 16-20) that the Cisco CME router sends to the phone. If the problem is that the call does not connect, you should look for the "OpenReceive" and "StartMedia" message exchanges (shown in Example 16-22) between the endpoints. The output of the debugs can be quite verbose. Looking for the key messages can help you identify the problem easier.

SCCP to H.323 Call

Figure 16-3 shows a sample exchange of messages between an H.323 endpoint and an SCCP endpoint during call setup and teardown. The exchange is very similar to the call setup discussed in the previous section except for the signaling messages specific to the H.323 protocol. You can view the call setup and teardown messages by turning on the debug h225 asn1 and debug h245 asn1 commands. The output of these debug commands shows the contents of the incoming and outgoing H.225 and H.245 messages.

Figure 16-3. H.323 to SCCP Call Setup Messages

Note

The output of debug commands can be quite verbose and shouldn't be turned on in Cisco CME in a production environment with large call volumes. Doing so can degrade the router's performance considerably.

Examples 16-24 and 16-25 show sample output of these debug messages. Example 16-24 shows the incoming H.225 setup messages. Relevant portions of the messages are highlighted to help you understand how to read them. The first line of the debug shows that it is an incoming H.225 message. Also, you can see that it is a setup message, which contains various other parameters, such as IP address and port number. These values are represented in hexadecimal.

Example 16-24. Debug Showing an H.225 Setup Message

CME_HQ# debug h225 asn1
*Jul 27 15:20:06.099: H225.0 INCOMING PDU ::= 
value H323_UserInformation ::=
 {
 h323-uu-pdu
 {
 h323-message-body setup : 
 {
 protocolIdentifier { 0 0 8 2250 0 4 }
 sourceInfo
 {
 vendor
 {
 vendor
 {
 t35CountryCode 181

 t35Extension 0
 manufacturerCode 18
 }
 }
 gateway
 {
 protocol
 {
 voice :
 {
 supportedPrefixes
 {
 }
 }
 }
 }
 mc FALSE
 undefinedNode FALSE
 }
 activeMC FALSE
 conferenceID 'D07ADDD6569911D68053CA040EE6AAC4'H
 conferenceGoal create : NULL
 callType pointToPoint : NULL
 sourceCallSignalAddress ipAddress : 
 { 
 ip '0A010201'H 
 port 11002
 }
 callIdentifier
 {
 guid 'D07ADDD6569911D68055CA040EE6AAC4'H
 }
 fastStart
 {
 '0000000D4001800B050001000A0102014B2B80'H
 '400000060401004D40018012150001000A010201...'H
 }
 mediaWaitForConnect FALSE
 canOverlapSend FALSE
 multipleCalls TRUE
 maintainConnection TRUE
 symmetricOperationRequired NULL
 }
 h245Tunneling TRUE
 nonStandardControl
 {

 {
 nonStandardIdentifier h221NonStandard :
 {
 t35CountryCode 181
 t35Extension 0
 manufacturerCode 18
 }
 data 'E0011200011C3B1C399E0100036774640000002E...'H
 }
 }
 tunnelledSignallingMessage
 {
 tunnelledProtocolID
 {
 id tunnelledProtocolAlternateID :
 {
 protocolType "gtd"
 }
 }
 messageContent
 {
 '49414D2C0D0A4743492C64303761646464363536...'H
 }
 }
 }
 }

*Jul 27 15:20:06.107: H225 NONSTD INCOMING ENCODE BUFFER::=
 E0011200011C3B1C399E0100036774640000002E49414D2C0D0A4743492C
 643037616464643635363939313164363830353363613034306565366161633
 40D0A0D0A088006000400000003
*Jul 27 15:20:06.107:
*Jul 27 15:20:06.107: H225 NONSTD INCOMING PDU ::=

value H323_UU_NonStdInfo ::=
 {
 version 18
 protoParam qsigNonStdInfo :
 {
 iei 28
 rawMesg '1C399E0100036774640000002E49414D2C0D0A47...'H
 }
 progIndParam progIndIEinfo :
 {
 progIndIE '00000003'H
 }
 }

Example 16-25 shows an H.245 "OpenLogicalChannel message", which is an outgoing message. You can also see the parameters such as codec, IP address of the gateway, and port address. Some of these debugs are used in the following chapters to discuss various trouble-shooting scenarios related to Cisco CME integration with H.323 endpoints and Cisco UE.

Example 16-25. Debug Showing an H.245 OpenLogicalChannel Message

CME_HQ#debug h245 asn1
*Jul 27 15:20:06.119: H245 FS OLC OUTGOING PDU ::=
value OpenLogicalChannel ::=
 {
 forwardLogicalChannelNumber 1
 forwardLogicalChannelParameters
 {
 dataType nullData : NULL
 multiplexParameters none : NULL
 }
 reverseLogicalChannelParameters
 {
 dataType audioData : g729 : 2 
 multiplexParameters h2250LogicalChannelParameters :
 {
 sessionID 1
 mediaChannel unicastAddress : iPAddress :
 {
 network '0A010201'H 
 tsapIdentifier 19242
 }
 mediaControlChannel unicastAddress : iPAddress :
 {
 network '0A010101'H
 tsapIdentifier 17373
 }
 silenceSuppression TRUE 
 }
 }
 }

When using the debugs shown in Examples 16-24 and 16-25, you should look for possible errors during a call setup. For example, a codec mismatch or a wrong IP address can cause the call to fail. By looking at the debugs, you can verify that the values exchanged during the call setup are correct. For example, the codec highlighted in Example 16-25 is G.729. Verify that this is the correct codec. Similarly, you can verify the IP address highlighted in Example 16-25 (in hexadecimal).

Note

You can convert the IP address shown in hexadecimal in the debug output by converting every two hexadecimal digits into binary. For example, the IP address for the hexadecimal value of 0A010101 is 10.1.1.1.

Troubleshooting the Cisco IPC Express GUI