Examples

The following is sample output from the debug voip application lpcorcommand for a call between two phones that was blocked by LPCOR policy validation:

Router# debug voip application lpcor
voip application AFW lpcor debugging is on CME# 
*Jun 24 11:24:58.115: //44//Dest:/DestOutboundCallUsingPeer: Save Lpcor Index 1 to Interworking Leg 
*Jun 24 11:24:58.119: //44//Dest:/DestProcessLPCOR: Peer 20002 Source Callid 44 CallType 0 *Jun 24 11:24:58.119: //44//Dest:/DestProcessLPCOR: lpcor source index(1) target index (2) ret_cause=63 
*Jun 24 11:24:58.119: //44//Dest:/DestSetup: lpcor block with peerTag 20002

Examples

Output is primarily used by TAC.

Examples

The following examples show output for variations of the debug voip ccapi command:

For these examples, the topology shown in the figure below is used.

Figure 1. Network Topology for debug voip ccapi Output Examples

Examples

Router# debug voip ccapi detail 
voip ccapi detail debugging is on
Router#
*Apr 18 20:35:35.779: //-1/ABCE697D8005/CCAPI/cc_api_call_setup_ind_common:
   Interface Type=13, Protocol=0
*Apr 18 20:35:35.779: //-1/ABCE697D8005/CCAPI/ccCheckClipClir:
   Calling Party Number Is User Provided
*Apr 18 20:35:35.779: //11/xxxxxxxxxxxx/CCAPI/cc_insert_call_entry:
   Total Call Count=0, Call Entry(Call Count On=FALSE, Incoming Call=TRUE)
*Apr 18 20:35:35.779: //11/xxxxxxxxxxxx/CCAPI/cc_insert_call_entry:
   Total Call Count=1

The following event shows that the CallEntry ID 11 is used for the incoming call leg.

*Apr 18 20:35:35.779: //11/ABCE697D8005/CCAPI/cc_insert_guid_pod_entry:
   Incoming=TRUE, Call Id=11
*Apr 18 20:35:35.779: //11/ABCE697D8005/CCAPI/cc_setupind_registration_lookup:
   Matching Parameters; Called Number=83103, Call Transfer Consult Id=
*Apr 18 20:35:35.779: //11/ABCE697D8005/CCAPI/cc_setupind_registration_lookup:
   No Matching Node
*Apr 18 20:35:35.779: //11/ABCE697D8005/CCAPI/ccCheckClipClir:
   Calling Party Number Is User Provided
*Apr 18 20:35:35.779: //12/xxxxxxxxxxxx/CCAPI/cc_insert_call_entry:
   Total Call Count=1, Call Entry(Call Count On=FALSE, Incoming Call=FALSE)

The following event shows that the incoming call leg with CallEntry ID 11 is bound to the outgoing call leg with CallEntry ID 12.

*Apr 18 20:35:35.779: //11/ABCE697D8005/CCAPI/cc_peer_bind:
   Bind=TRUE, Binder Call Id=11, Bindee Call Id=12

The next event shows that CallEntry ID 12 is used for the outgoing call leg.

*Apr 18 20:35:35.779: //12/ABCE697D8005/CCAPI/cc_insert_guid_pod_entry:
   Incoming=FALSE, Call Id=12
*Apr 18 20:35:35.779: //-1/xxxxxxxxxxxx/CCAPI/cc_api_supported_data:
   data_mode=0x10082

The next event shows an IP address for a remote device on the outgoing call leg, which indicates that this is the VoIP call leg.

*Apr 18 20:35:35.779: //12/ABCE697D8005/CCAPI/cc_incr_if_call_volume:
   Remote IP Address=172.16.13.81, Hwidb=FastEthernet0/0
*Apr 18 20:35:35.779: //12/ABCE697D8005/CCAPI/cc_incr_if_call_volume:
   Total Call Count=1, Voip Call Count=1, MMoip Call Count=0
*Apr 18 20:35:35.795: //11/ABCE697D8005/CCAPI/ccCallGetContext:
   Context=0x652C0168, Call Id=11
*Apr 18 20:36:31.419: //11/ABCE697D8005/CCAPI/ccCallDisconnect:
   Start Calling Accounting;
   Call Entry(Incoming=TRUE)
*Apr 18 20:36:31.419: //11/ABCE697D8005/CCAPI/ccCallDisconnect:
   Cause Value=16, Call Entry(Disconnect Cause=16)
*Apr 18 20:36:31.419: //11/ABCE697D8005/CCAPI/ccCallDisconnect:
   Call Entry(Disconnect Cause=16)

At this point, the CallEntry ID changes as the call accounting process begins. The accounting data is sent over the outgoing call leg. The GUID, which identifies the unique call, remains the same.

*Apr 18 20:36:31.419: //12/ABCE697D8005/CCAPI/ccCallDisconnect:
   Start Calling Accounting;
   Call Entry(Incoming=FALSE)
*Apr 18 20:36:31.419: //12/ABCE697D8005/CCAPI/ccCallDisconnect:
   Cause Value=16, Call Entry(Disconnect Cause=0)

The change of the CallEntry ID indicates that the call is using the incoming call leg, which is the POTS call leg in this case.

*Apr 18 20:36:31.423: //11/ABCE697D8005/CCAPI/ccCallGetVoipFlag:
   Data Bitmask=0x1, Call Id=11
*Apr 18 20:36:31.423: //11/ABCE697D8005/CCAPI/ccCallGetVoipFlag:
   Flag=FALSE
*Apr 18 20:36:31.423: //11/ABCE697D8005/CCAPI/cc_delete_guid_pod_entry:
   Incoming=TRUE
*Apr 18 20:36:31.423: //11/ABCE697D8005/CCAPI/cc_delete_call_entry:
   ccFreeRawMsgInfo=0x63FF8198
*Apr 18 20:36:31.423: //11/ABCE697D8005/CCAPI/cc_delete_call_entry:
   Total Call Count=1, Call Entry(Call Count On=FALSE, Incoming Call=TRUE)
*Apr 18 20:36:31.423: //11/ABCE697D8005/CCAPI/cc_delete_call_entry:
   Total Call Count=0
*Apr 18 20:36:31.423: //11/ABCE697D8005/CCAPI/cc_delete_call_entry:
   Deleting profileTable[0x64F44700]

The next line shows the impairment calculation. This is the only CCAPI debug command that shows impairment.

*Apr 18 20:36:31.423: //-1/ABCE697D8005/CCAPI/g113_calculate_impairment:
   (delay=91(ms), loss=0%), Io=0 Iq=0 Idte=0 Idd=2 Ie=10 Itot=12
*Apr 18 20:36:31.423: //12/ABCE697D8005/CCAPI/ccCallGetVoipFlag:
   Data Bitmask=0x1, Call Id=12
*Apr 18 20:36:31.423: //12/ABCE697D8005/CCAPI/ccCallGetVoipFlag:
   Flag=FALSE
*Apr 18 20:36:31.423: //12/ABCE697D8005/CCAPI/cc_decr_if_call_volume:
   Remote IP Address=172.16.13.81, Hwidb=FastEthernet0/0
*Apr 18 20:36:31.423: //12/ABCE697D8005/CCAPI/cc_decr_if_call_volume:
   Total Call Count=0, Voip Call Count=0, MMoip Call Count=0
*Apr 18 20:36:31.423: //12/ABCE697D8005/CCAPI/cc_delete_guid_pod_entry:
   Incoming=FALSE
*Apr 18 20:36:31.423: //12/ABCE697D8005/CCAPI/cc_delete_call_entry:
   Total Call Count=0, Call Entry(Call Count On=FALSE, Incoming Call=FALSE)
*Apr 18 20:36:31.423: //12/ABCE697D8005/CCAPI/cc_delete_call_entry:
   Deleting profileTable[0x652E3310]
*Apr 18 20:36:31.427: //12/xxxxxxxxxxxx/CCAPI/cc_get_call_entry:
   Call Entry Is Not Found

Examples

Router# debug voip ccapi detail 
voip ccapi detail debugging is on
Router#
*May  1 18:58:26.251: //-1/xxxxxxxxxxxx/CCAPI/cc_api_supported_data:
   data_mode=0x10082
*May  1 18:58:26.255: //8/xxxxxxxxxxxx/CCAPI/cc_get_call_entry:
   Call Entry Is Not Found
*May  1 18:58:26.255: //-1/ABCE697D8005/CCAPI/cc_api_call_setup_ind_common:
   Interface Type=0, Protocol=1
*May  1 18:58:26.255: //-1/ABCE697D8005/CCAPI/ccCheckClipClir:
   Calling Party Number Is User Provided

The following line shows the attributes of the calling number:

*May  1 18:58:26.255: //-1/ABCE697D8005/CCAPI/cc_api_call_setup_ind_common:
   After Number Translation Checking:
   Calling Number=4085550111(TON=National, NPI=ISDN, Screening=User, Passed, Presentation=Allowed),
   Called Number=3600(TON=Unknown, NPI=Unknown)
*May  1 18:58:26.255: //8/xxxxxxxxxxxx/CCAPI/cc_insert_call_entry:
   Total Call Count=0, Call Entry(Call Count On=FALSE, Incoming Call=TRUE)
*May  1 18:58:26.255: //8/xxxxxxxxxxxx/CCAPI/cc_insert_call_entry:
   Total Call Count=1
*May  1 18:58:26.255: //8/ABCE697D8005/CCAPI/cc_insert_guid_pod_entry:
   Incoming=TRUE, Call Id=8

The following line shows the IP address of the originating gateway:

*May  1 18:58:26.255: //8/ABCE697D8005/CCAPI/cc_incr_if_call_volume:
   Remote IP Address=172.16.13.175, Hwidb=FastEthernet0/0
*May  1 18:58:26.255: //8/ABCE697D8005/CCAPI/cc_incr_if_call_volume:
   Total Call Count=1, Voip Call Count=1, MMoip Call Count=0
*May  1 18:58:26.255: //8/ABCE697D8005/CCAPI/cc_setupind_registration_lookup:
   Matching Parameters; Called Number=3600, Call Transfer Consult Id=
*May  1 18:58:26.255: //8/ABCE697D8005/CCAPI/cc_setupind_registration_lookup:
   No Matching Node
*May  1 18:58:26.255: //8/ABCE697D8005/CCAPI/ccCheckClipClir:
   Calling Party Number Is User Provided
*May  1 18:58:26.259: //9/xxxxxxxxxxxx/CCAPI/cc_insert_call_entry:
   Total Call Count=1, Call Entry(Call Count On=FALSE, Incoming Call=FALSE)
*May  1 18:58:26.259: //8/ABCE697D8005/CCAPI/cc_peer_bind:
   Bind=TRUE, Binder Call Id=8, Bindee Call Id=9
*May  1 18:58:26.259: //9/ABCE697D8005/CCAPI/cc_insert_guid_pod_entry:
   Incoming=FALSE, Call Id=9
*May  1 18:58:26.259: //9/ABCE697D8005/CCAPI/cc_set_voice_port_value:
   CC_IF_TELEPHONY: Echo=0, Playout=0
*May  1 18:58:26.263: //9/ABCE697D8005/CCAPI/ccCallGetContext:
   Context=0x64B6BB5C, Call Id=9
*May  1 18:59:21.871: //8/ABCE697D8005/CCAPI/ccCallDisconnect:
   Start Calling Accounting;
   Call Entry(Incoming=TRUE)
*May  1 18:59:21.875: //8/ABCE697D8005/CCAPI/ccCallDisconnect:
   Cause Value=16, Call Entry(Disconnect Cause=16)
*May  1 18:59:21.875: //8/ABCE697D8005/CCAPI/ccCallDisconnect:
   Call Entry(Disconnect Cause=16)
*May  1 18:59:21.875: //9/ABCE697D8005/CCAPI/ccCallDisconnect:
   Start Calling Accounting;
   Call Entry(Incoming=FALSE)
*May  1 18:59:21.875: //9/ABCE697D8005/CCAPI/ccCallDisconnect:
   Cause Value=16, Call Entry(Disconnect Cause=0)

The next line shows the impairment calculation. This is the only CCAPI debug command that shows impairment.

*May  1 18:59:21.875: //-1/ABCE697D8005/CCAPI/g113_calculate_impairment:
   (delay=99(ms), loss=0%), Io=0 Iq=0 Idte=0 Idd=2 Ie=10 Itot=12
*May  1 18:59:21.875: //8/ABCE697D8005/CCAPI/ccCallGetVoipFlag:
   Data Bitmask=0x1, Call Id=8
*May  1 18:59:21.875: //8/ABCE697D8005/CCAPI/ccCallGetVoipFlag:
   Flag=FALSE
*May  1 18:59:21.875: //8/ABCE697D8005/CCAPI/cc_decr_if_call_volume:
   Remote IP Address=172.16.13.175, Hwidb=FastEthernet0/0
*May  1 18:59:21.875: //8/ABCE697D8005/CCAPI/cc_decr_if_call_volume:
   Total Call Count=0, Voip Call Count=0, MMoip Call Count=0
*May  1 18:59:21.875: //8/ABCE697D8005/CCAPI/cc_delete_guid_pod_entry:
   Incoming=TRUE
*May  1 18:59:21.875: //8/ABCE697D8005/CCAPI/cc_delete_call_entry:
   ccFreeRawMsgInfo=0x644EB850
Router#
*May  1 18:59:21.875: //8/ABCE697D8005/CCAPI/cc_delete_call_entry:
   Total Call Count=1, Call Entry(Call Count On=FALSE, Incoming Call=TRUE)
*May  1 18:59:21.875: //8/ABCE697D8005/CCAPI/cc_delete_call_entry:
   Total Call Count=0
*May  1 18:59:21.879: //8/ABCE697D8005/CCAPI/cc_delete_call_entry:
   Deleting profileTable[0x64B78600]
*May  1 18:59:21.879: //8/xxxxxxxxxxxx/CCAPI/cc_get_call_entry:
   Call Entry Is Not Found
*May  1 18:59:21.879: //8/xxxxxxxxxxxx/CCAPI/cc_get_call_entry:
   Call Entry Is Not Found
Router#
*May  1 18:59:24.587: //9/ABCE697D8005/CCAPI/ccCallGetVoipFlag:
   Data Bitmask=0x1, Call Id=9
*May  1 18:59:24.587: //9/ABCE697D8005/CCAPI/ccCallGetVoipFlag:
   Flag=FALSE
*May  1 18:59:24.587: //9/ABCE697D8005/CCAPI/cc_api_call_disconnect_done:
   Prefix Is Not Defined From Peer; Peer=3600, Called Number=3600
*May  1 18:59:24.587: //9/ABCE697D8005/CCAPI/cc_delete_guid_pod_entry:
   Incoming=FALSE
*May  1 18:59:24.587: //9/ABCE697D8005/CCAPI/cc_delete_call_entry:
   Total Call Count=0, Call Entry(Call Count On=FALSE, Incoming Call=FALSE)
*May  1 18:59:24.587: //9/ABCE697D8005/CCAPI/cc_delete_call_entry:
   Deleting profileTable[0x6453F228]

Examples

Router# debug voip ccapi inout 
voip ccapi inout debugging is on
Router#
*Apr 18 20:42:19.347: //-1/9C5A9CA88009/CCAPI/cc_api_display_ie_subfields:
   cc_api_call_setup_ind_common:
   acme-username=
   ----- ccCallInfo IE subfields -----
   acme-ani=4085550111
   acme-anitype=2
   acme-aniplan=1
   acme-anipi=0
   acme-anisi=1
   dest=83103
   acme-desttype=0
   acme-destplan=0
   acme-rdn=
   acme-rdntype=-1
   acme-rdnplan=-1
   acme-rdnpi=-1
   acme-rdnsi=-1
   acme-redirectreason=-1

The following lines show information about the calling and called numbers. The network presentation indicator (NPI) shows the type of transmission. The Incoming Dial-Peer field shows that the incoming dial peer has been matched.

*Apr 18 20:42:19.347: //-1/9C5A9CA88009/CCAPI/cc_api_call_setup_ind_common:
   Interface=0x64F26F10, Call Info(
   Calling Number=4085550111(TON=National, NPI=ISDN, Screening=User, Passed, Presentation=Allowed),
   Called Number=83103(TON=Unknown, NPI=Unknown),
   Calling Translated=FALSE, Subsriber Type Str=RegularLine, FinalDestinationFlag=TRUE,
   Incoming Dial-peer=1, Progress Indication=NULL(0), Calling IE Present=TRUE,
   Source Trkgrp Route Label=, Target Trkgrp Route Label=, CLID Transparent=FALSE), Call Id=-1
*Apr 18 20:42:19.347: //-1/9C5A9CA88009/CCAPI/ccCheckClipClir:
   In: Calling Number=4085550111(TON=National, NPI=ISDN, Screening=User, Passed, Presentation=Allowed)
*Apr 18 20:42:19.347: //-1/9C5A9CA88009/CCAPI/ccCheckClipClir:
   Out: Calling Number=4085550111(TON=National, NPI=ISDN, Screening=User, Passed, Presentation=Allowed)

In the following event, the call leg is established. The CallEntry ID field changes from-1 to 19.

*Apr 18 20:42:19.347: //19/9C5A9CA88009/CCAPI/cc_api_call_setup_ind_common:
   Set Up Event Sent;
   Call Info(Calling Number=4085550111(TON=National, NPI=ISDN, Screening=User, Passed, Presentation=Allowed),
   Called Number=83103(TON=Unknown, NPI=Unknown))
*Apr 18 20:42:19.351: //19/9C5A9CA88009/CCAPI/cc_process_call_setup_ind:
   Event=0x63FF4730
*Apr 18 20:42:19.351: //19/9C5A9CA88009/CCAPI/ccCallSetContext:
   Context=0x652A9858
*Apr 18 20:42:19.351: //19/9C5A9CA88009/CCAPI/cc_process_call_setup_ind:
   >>>>CCAPI handed cid 19 with tag 1 to app "Default"
*Apr 18 20:42:19.351: //19/9C5A9CA88009/CCAPI/ccCallProceeding:
   Progress Indication=NULL(0)
*Apr 18 20:42:19.351: //19/9C5A9CA88009/CCAPI/ccCallSetupRequest:
   Destination=, Calling IE Present=TRUE, Mode=0,
   Outgoing Dial-peer=3600, Params=0x652AA4A8, Progress Indication=NULL(0)
*Apr 18 20:42:19.351: //19/9C5A9CA88009/CCAPI/ccCheckClipClir:
   In: Calling Number=4085550111(TON=National, NPI=ISDN, Screening=User, Passed, Presentation=Allowed)
*Apr 18 20:42:19.351: //19/9C5A9CA88009/CCAPI/ccCheckClipClir:
   Out: Calling Number=4085550111(TON=National, NPI=ISDN, Screening=User, Passed, Presentation=Allowed)
*Apr 18 20:42:19.351: //19/9C5A9CA88009/CCAPI/ccCallSetupRequest:
   Destination Pattern=360., Called Number=3600, Digit Strip=FALSE
*Apr 18 20:42:19.351: //19/9C5A9CA88009/CCAPI/ccCallSetupRequest:
   Calling Number=4085550111(TON=National, NPI=ISDN, Screening=User, Passed, Presentation=Allowed),
   Called Number=3600(TON=Unknown, NPI=Unknown),
   Redirect Number=, Display Info=
   Account Number=, Final Destination Flag=TRUE,
   Guid=9C5A9CA8-5243-11D6-8009-00059A3A15A0, Outgoing Dial-peer=3600
*Apr 18 20:42:19.351: //19/9C5A9CA88009/CCAPI/cc_api_display_ie_subfields:
   ccCallSetupRequest:
   cisco-username=
   ----- ccCallInfo IE subfields -----
   cisco-ani=4085550111
   cisco-anitype=2
   cisco-aniplan=1
   cisco-anipi=0
   cisco-anisi=1
   dest=3600
   cisco-desttype=0
   cisco-destplan=0
   cisco-rdn=
   cisco-rdntype=-1
   cisco-rdnplan=-1
   cisco-rdnpi=-1
   cisco-rdnsi=-1
   cisco-redirectreason=-1

In the following lines, the outgoing dial peer is matched:

*Apr 18 20:42:19.351: //19/9C5A9CA88009/CCAPI/ccIFCallSetupRequestPrivate:
   Interface=0x63EAF24C, Interface Type=1, Destination=, Mode=0x0,
   Call Params(Calling Number=4085550111(TON=National, NPI=ISDN, Screening=User, Passed, Presentation=Allowed),
   Called Number=3600(TON=Unknown, NPI=Unknown), Calling Translated=FALSE,
   Subsriber Type Str=RegularLine, FinalDestinationFlag=TRUE, Outgoing Dial-peer=3600, Call Count On=FALSE,
   Source Trkgrp Route Label=, Target Trkgrp Route Label=, tg_label_flag=0, Application Call Id=)
*Apr 18 20:42:19.351: //20/9C5A9CA88009/CCAPI/ccIFCallSetupRequestPrivate:
   SPI Call Setup Request Is Success; Interface Type=1, FlowMode=1
*Apr 18 20:42:19.351: //20/9C5A9CA88009/CCAPI/ccCallSetContext:
   Context=0x652AA458
*Apr 18 20:42:19.351: //19/9C5A9CA88009/CCAPI/ccSaveDialpeerTag:
   Outgoing Dial-peer=3600
*Apr 18 20:42:19.351: //19/9C5A9CA88009/CCAPI/ccSaveDialpeerTag:
   Outgoing Dial-peer=3600
*Apr 18 20:42:19.367: //20/9C5A9CA88009/CCAPI/cc_api_call_proceeding:
   Interface=0x652F6388, Progress Indication=NULL(0)

The following lines show call progress. The progress and signal indications are shown.

*Apr 18 20:42:19.371: //20/9C5A9CA88009/CCAPI/cc_api_call_cut_progress:
   Interface=0x652F6388, Progress Indication=INBAND(8), Signal Indication=SIGNAL RINGBACK(1),
   Cause Value=0
*Apr 18 20:42:19.371: //20/9C5A9CA88009/CCAPI/cc_api_call_cut_progress:
   Call Entry(Responsed=TRUE)
*Apr 18 20:42:19.371: //19/9C5A9CA88009/CCAPI/ccCallCutProgress:
   Progress Indication=INBAND(8), Signal Indication=SIGNAL RINGBACK(1), Cause Value=0
   Voice Call Send Alert=FALSE, Call Entry(AlertSent=FALSE)
*Apr 18 20:42:19.371: //19/9C5A9CA88009/CCAPI/ccCallCutProgress:
   Call Entry(Responsed=TRUE)

The following lines show the tone generation information:

*Apr 18 20:42:19.371: //19/9C5A9CA88009/CCAPI/ccGenerateToneInfo:
   Stop Tone On Digit=FALSE, Tone=Null,
   Tone Direction=Network, Params=0x0, Call Id=19
*Apr 18 20:42:19.371: //19/9C5A9CA88009/CCAPI/ccConferenceCreate:
   Conference Id=0x652F723C, Call Id1=19, Call Id2=20, Tag=0x0
*Apr 18 20:42:19.371: //20/xxxxxxxxxxxx/CCAPI/cc_api_bridge_done:
   Conference Id=0x6, Source Interface=0x63EAF24C, Source Call Id=20,
   Destination Call Id=19, Disposition=0x0, Tag=0x0
*Apr 18 20:42:19.371: //19/9C5A9CA88009/CCAPI/ccConferenceCreate:
   Call Entry(Conference Id=0x6, Destination Call Id=20)
*Apr 18 20:42:19.371: //20/9C5A9CA88009/CCAPI/ccConferenceCreate:
   Call Entry(Conference Id=0x6, Destination Call Id=19)
*Apr 18 20:42:19.371: //19/xxxxxxxxxxxx/CCAPI/cc_api_bridge_done:
   Conference Id=0x6, Source Interface=0x64F26F10, Source Call Id=19,
   Destination Call Id=20, Disposition=0x0, Tag=0x0
*Apr 18 20:42:19.371: //19/9C5A9CA88009/CCAPI/cc_generic_bridge_done:
   Conference Id=0x6, Source Interface=0x64F26F10, Source Call Id=19,
   Destination Call Id=20, Disposition=0x0, Tag=0x0
*Apr 18 20:42:19.371: //19/9C5A9CA88009/CCAPI/cc_api_caps_ind:
   Destination Interface=0x63EAF24C, Destination Call Id=20, Source Call Id=19,
   Caps(Codec=0x2887F, Fax Rate=0xBF, Vad=0x3,
   Modem=0x2, Codec Bytes=0, Signal Type=3)
*Apr 18 20:42:19.371: //19/9C5A9CA88009/CCAPI/cc_api_caps_ind:
   Caps(Playout Mode=1, Playout Initial=60(ms), Playout Min=40(ms),
   Playout Max=300(ms), Fax Nom=300(ms))
*Apr 18 20:42:19.371: //19/9C5A9CA88009/CCAPI/cc_process_notify_bridge_done:
   Conference Id=0x6, Call Id1=19, Call Id2=20
*Apr 18 20:42:19.375: //20/9C5A9CA88009/CCAPI/cc_api_caps_ind:
   Destination Interface=0x64F26F10, Destination Call Id=19, Source Call Id=20,
   Caps(Codec=0x4, Fax Rate=0x1, Vad=0x2,
   Modem=0x2, Codec Bytes=20, Signal Type=2)
*Apr 18 20:42:19.375: //20/9C5A9CA88009/CCAPI/cc_api_caps_ind:
   Caps(Playout Mode=1, Playout Initial=60(ms), Playout Min=40(ms),
   Playout Max=300(ms), Fax Nom=300(ms))

The following lines show codec information:

*Apr 18 20:42:19.375: //20/9C5A9CA88009/CCAPI/cc_api_caps_ack:
   Destination Interface=0x64F26F10, Destination Call Id=19, Source Call Id=20,
   Caps(Codec=g729r8(0x4), Fax Rate=FAX_RATE_NONE(0x1), Vad=ON(0x2),
   Modem=ON(0x2), Codec Bytes=20, Signal Type=2, Seq Num Start=6872)
*Apr 18 20:42:19.375: //19/9C5A9CA88009/CCAPI/cc_api_caps_ack:
   Destination Interface=0x63EAF24C, Destination Call Id=20, Source Call Id=19,
   Caps(Codec=g729r8(0x4), Fax Rate=FAX_RATE_NONE(0x1), Vad=ON(0x2),
   Modem=ON(0x2), Codec Bytes=20, Signal Type=2, Seq Num Start=6872)
*Apr 18 20:42:19.375: //19/9C5A9CA88009/CCAPI/cc_api_voice_mode_event:
   Call Id=19
*Apr 18 20:42:19.375: //19/9C5A9CA88009/CCAPI/cc_api_voice_mode_event:
   Call Entry(Context=0x652A9858)

The following lines show progress indication information. In this case, the event shows that the destination is not ISDN.

*Apr 18 20:42:26.855: //20/9C5A9CA88009/CCAPI/cc_api_call_connected:
   Interface=0x652F6388, Data Bitmask=0x0, Progress Indication=DESTINATION IS NON ISDN(2),
   Connection Handle=0
*Apr 18 20:42:26.855: //20/9C5A9CA88009/CCAPI/cc_api_call_connected:
   Call Entry(Connected=TRUE, Responsed=TRUE, Retry Count=0)
*Apr 18 20:42:26.855: //19/9C5A9CA88009/CCAPI/ccCallConnect:
   Progress Indication=DESTINATION IS NON ISDN(2), Data Bitmask=0x0
*Apr 18 20:42:26.855: //19/9C5A9CA88009/CCAPI/ccCallConnect:
   Call Entry(Connected=TRUE, Responsed=TRUE)
*Apr 18 20:42:26.855: //20/9C5A9CA88009/CCAPI/ccSaveDialpeerTag:
   Incoming Dial-peer=1
*Apr 18 20:42:26.859: //19/9C5A9CA88009/CCAPI/ccSaveDialpeerTag:
   Outgoing Dial-peer=3600
*Apr 18 20:42:26.859: //20/9C5A9CA88009/CCAPI/ccCallFeature:
   Feature Type=24, Call Id=20

This event shows that the call is disconnected.

*Apr 18 20:43:16.795: //19/9C5A9CA88009/CCAPI/cc_api_call_disconnected:
   Cause Value=16, Interface=0x64F26F10, Call Id=19
*Apr 18 20:43:16.795: //19/9C5A9CA88009/CCAPI/cc_api_call_disconnected:
   Call Entry(Responsed=TRUE, Cause Value=16, Retry Count=0)
*Apr 18 20:43:16.795: //19/9C5A9CA88009/CCAPI/ccConferenceDestroy:
   Conference Id=0x6, Tag=0x0
*Apr 18 20:43:16.795: //20/xxxxxxxxxxxx/CCAPI/cc_api_bridge_drop_done:
   Conference Id=0x6, Source Interface=0x63EAF24C, Source Call Id=20,
   Destination Call Id=19, Disposition=0x0, Tag=0x0
*Apr 18 20:43:16.795: //19/xxxxxxxxxxxx/CCAPI/cc_api_bridge_drop_done:
   Conference Id=0x6, Source Interface=0x64F26F10, Source Call Id=19,
   Destination Call Id=20, Disposition=0x0, Tag=0x0
*Apr 18 20:43:16.795: //19/9C5A9CA88009/CCAPI/cc_generic_bridge_done:
   Conference Id=0x6, Source Interface=0x64F26F10, Source Call Id=19,
   Destination Call Id=20, Disposition=0x0, Tag=0x0
*Apr 18 20:43:16.795: //19/9C5A9CA88009/CCAPI/ccCallDisconnect:
   Cause Value=16, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=16)
*Apr 18 20:43:16.795: //19/9C5A9CA88009/CCAPI/ccCallDisconnect:
   Cause Value=16, Call Entry(Responsed=TRUE, Cause Value=16)
*Apr 18 20:43:16.795: //19/9C5A9CA88009/CCAPI/cc_api_get_transfer_info:
   Transfer Number Is Null
*Apr 18 20:43:16.795: //20/9C5A9CA88009/CCAPI/ccCallDisconnect:
   Cause Value=16, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=0)
*Apr 18 20:43:16.795: //20/9C5A9CA88009/CCAPI/ccCallDisconnect:
   Cause Value=16, Call Entry(Responsed=TRUE, Cause Value=16)
*Apr 18 20:43:16.795: //20/9C5A9CA88009/CCAPI/cc_api_get_transfer_info:
   Transfer Number Is Null
*Apr 18 20:43:16.803: //20/9C5A9CA88009/CCAPI/cc_api_call_disconnect_done:
   Disposition=0, Interface=0x652F6388, Tag=0x0, Call Id=20,
   Call Entry(Disconnect Cause=16, Voice Class Cause Code=0, Retry Count=0)
*Apr 18 20:43:16.803: //20/9C5A9CA88009/CCAPI/cc_api_call_disconnect_done:
   Call Disconnect Event Sent
*Apr 18 20:43:16.803: //19/9C5A9CA88009/CCAPI/cc_api_call_disconnect_done:
   Disposition=0, Interface=0x64F26F10, Tag=0x0, Call Id=19,
   Call Entry(Disconnect Cause=16, Voice Class Cause Code=0, Retry Count=0)
*Apr 18 20:43:16.803: //19/9C5A9CA88009/CCAPI/cc_api_call_disconnect_done:
   Call Disconnect Event Sent

Examples

Router# debug voip ccapi service
 
voip ccapi service debugging is on
*May  1 19:08:41.803: //-1/xxxxxxxxxxxx/CCAPI/cc_setupind_match_search:
   Searching Node;
   Called Number=3600, Call Transfer Consult Id=

This debug shows noncall related events. In this case, information about the timer is shown.

*May  1 19:08:48.027: //-1/xxxxxxxxxxxx/CCAPI/cc_handle_periodic_timer:
   Calling The Callback, ccTimerctx=0x63B368C0
*May  1 19:08:48.027: //-1/xxxxxxxxxxxx/CCAPI/ccTimerStart:
   ccTimerctx=0x63B368C0
*May  1 19:10:08.615: //-1/xxxxxxxxxxxx/CCAPI/cc_api_icpif:
   ExpectFactor=0xA

Examples

This debug shows the preemption tone timer getting initiated.

*Aug 24 18:28:16.919: //18958/B37648B6AF48/CCAPI/cc_api_call_preempt_ind:
   PreemptionToneTimer=10(s)

Examples

The following example shows the call setup indicated and accepted by the voice gateway:

Router# debug voip ccapi inout
*Mar  1 15:35:53.588: //-1/xxxxxxxxxxxx/CCAPI/ccTDConstructTDUsrContainer: 
usrContainer[0x638C1BF0], magic[FACE0FFF]
*Mar  1 15:35:53.592: //-1/xxxxxxxxxxxx/CCAPI/ccTDUtilAddDataToUsrContainer: 
container=0x638C1BF0, tagID=6, dataSize=16, instID=-1,modifier=1
*Mar  1 15:35:53.592: //-1/xxxxxxxxxxxx/CCAPI/ccTDConstructInstanceTDObject: 
tdObject[0x638BC1AC], nxtElem[0x0], magic[0xFACE0FFF] tagID[6], dataLen[16], 
modif[1]
*Mar  1 15:35:53.592: //-1/xxxxxxxxxxxx/CCAPI/ccTDPvtAddObjectToContainer: 
Adding tdObject[0x638BC1AC] instID[-1] into container[0x638C1BF0]
*Mar  1 15:35:53.592: //-1/xxxxxxxxxxxx/CCAPI/ccTDUtilAddDataToUsrContainer: 
container=0x638C1BF0, tagID=5, dataSize=276, instID=-1,modifier=1
*Mar  1 15:35:53.592: //-1/xxxxxxxxxxxx/CCAPI/ccTDConstructInstanceTDObject: 
tdObject[0x63401148], nxtElem[0x0], magic[0xFACE0FFF] tagID[5], dataLen[276], 
modif[1]
*Mar  1 15:35:53.592: //-1/xxxxxxxxxxxx/CCAPI/ccTDPvtAddObjectToContainer: 
Adding tdObject[0x63401148] instID[-1] into container[0x638C1BF0]

In the following lines, the call control API (CCAPI) receives the call setup. The called number is 34999, and the calling number is 55555. The calling number matches dial peer 10002.

*Mar  1 15:35:53.592: //-1/xxxxxxxxxxxx/CCAPI/cc_api_display_ie_subfields:
*Mar  1 15:35:53.592: cc_api_call_setup_ind:
*Mar  1 15:35:53.592:  cisco-username=
*Mar  1 15:35:53.596: ----- ccCallInfo IE subfields -----
*Mar  1 15:35:53.596:  cisco-ani=55555
*Mar  1 15:35:53.596:  cisco-anitype=0
*Mar  1 15:35:53.596:  cisco-aniplan=0
*Mar  1 15:35:53.596:  cisco-anipi=0 
*Mar  1 15:35:53.596:  cisco-anisi=0
*Mar  1 15:35:53.596:  dest=34999
*Mar  1 15:35:53.596:  cisco-desttype=0
*Mar  1 15:35:53.596:  cisco-destplan=0 
*Mar  1 15:35:53.596:  cisco-rdn=
*Mar  1 15:35:53.596:  cisco-rdntype=-1
*Mar  1 15:35:53.596:  cisco-rdnplan=-1 
*Mar  1 15:35:53.596:  cisco-rdnpi=-1
*Mar  1 15:35:53.596:  cisco-rdnsi=-1
*Mar  1 15:35:53.596:  cisco-redirectreason=-1
*Mar  1 15:35:53.596: //-1/xxxxxxxxxxxx/CCAPI/cc_api_call_setup_ind: 
(vdbPtr=0x637EC1E0, callInfo={called=34999,called_oct3=0x80,calling=55555,calling_oct3=0x80,calling_oct3a=0x0,calling_xlated=false,subscriber_type_str=RegularLine,fdest=1,
peer_tag=10002, prog_ind=0,callingIE_present 1, src_route_label=, tgt_route_label= clid_transparent=0},callID=0x637B4278)
*Mar  1 15:35:53.596: //-1/xxxxxxxxxxxx/CCAPI/cc_api_call_setup_ind:
*Mar  1 15:35:53.596: //-1/xxxxxxxxxxxx/CCAPI/cc_api_call_setup_ind: type 13 , prot 0
*Mar  1 15:35:53.596: //-1/xxxxxxxxxxxx/CCAPI/ccCheckClipClir:
*Mar  1 15:35:53.596: ccCheckClipClir: calling number is: "55555", calling oct3a is: 0x0
*Mar  1 15:35:53.596: //-1/xxxxxxxxxxxx/CCAPI/ccCheckClipClir:
*Mar  1 15:35:53.596: Calling Party number is User Provided
*Mar  1 15:35:53.596: //-1/xxxxxxxxxxxx/CCAPI/ccCheckClipClir:
*Mar  1 15:35:53.596: Leaving ccCheckClipClir
  calling number is: "55555"
  calling oct3 is:  0x80
  calling oct3a is: 0x0

In the next line, 44 is the CallEntry ID.

*Mar  1 15:35:53.600: //44/xxxxxxxxxxxx/CCAPI/cc_insert_call_entry: Increment call volume: 0 
*Mar  1 15:35:53.600: //44/xxxxxxxxxxxx/CCAPI/cc_insert_call_entry: current call volume: 1
*Mar  1 15:35:53.600: //44/xxxxxxxxxxxx/CCAPI/cc_insert_call_entry: entry's incoming TRUE.
*Mar  1 15:35:53.600: //44/xxxxxxxxxxxx/CCAPI/cc_insert_call_entry: is_incoming is TRUE
*Mar  1 15:35:53.600: //-1/xxxxxxxxxxxx/CCAPI/ccTDConstructHashProfileTab: profileTable[0x6380E11C], numBuckets[11], numEntries[0]
*Mar  1 15:35:53.600: //-1/xxxxxxxxxxxx/CCAPI/ccTDPvtProfileTableBuildManager: Invoking necessary profileTable updaters...
*Mar  1 15:35:53.600: //-1/xxxxxxxxxxxx/CCAPI/ccTDPvtUpdateProfileTabFromContainer: Updating profileTable[0x6380E11C] with objects in container[0x638C1BF0]
*Mar  1 15:35:53.600: //-1/xxxxxxxxxxxx/CCAPI/ccTDPvtUpdateProfileTabFromContainer: obtained key[5] for the tag[6]
*Mar  1 15:35:53.600: //-1/xxxxxxxxxxxx/CCAPI/ccTDPvtAddObjectToProfileBucket: profileTable[0x6380E11C], tdObject[0x638BC1AC]
*Mar  1 15:35:53.600: //-1/xxxxxxxxxxxx/CCAPI/ccTDPvtUpdateProfileTabFromContainer: obtained key[0] for the tag[5]
*Mar  1 15:35:53.600: //-1/xxxxxxxxxxxx/CCAPI/ccTDPvtAddObjectToProfileBucket: profileTable[0x6380E11C], tdObject[0x63401148]
*Mar  1 15:35:53.600: //-1/xxxxxxxxxxxx/CCAPI/ccTDPvtProfileTableBuildManager:
*Mar  1 15:35:53.600: ccTDUtilDumpAllElemInProfileTab: profileTable[0x6380E11C],
 numBuckets[11], numEntries[2]
*Mar  1 15:35:53.600: Bucket { 0 } ------>0x63401148[0x0,t-5,l-276,d-0x63401168,
m-1,u-56153,g-FACE0FFF]
*Mar  1 15:35:53.604:
*Mar  1 15:35:53.604: Bucket { 5 } ------>0x638BC1AC[0x0,t-6,l-16,d-0x638BC1CC,m-1,u-56153,g-FACE0FFF]
*Mar  1 15:35:53.604:
*Mar  1 15:35:53.604: //-1/xxxxxxxxxxxx/CCAPI/ccTDDestructTDUsrContainer: Container[0x638C1BF0]
*Mar  1 15:35:53.604: //-1/xxxxxxxxxxxx/CCAPI/cc_incr_if_call_volume: not the VoIP or MMoIP
*Mar  1 15:35:53.608: //-1/xxxxxxxxxxxx/CCAPI/cc_process_call_setup_ind: (event=
0x63073AA0)

In the next line, 45F2AAE28044 is the GUID. The tag 10002 entry shows that the incoming dial peer matched the CallEntry ID.

*Mar  1 15:35:53.608: //44/45F2AAE28044/CCAPI/cc_process_call_setup_ind: >>>>CCAPI handed cid 44 with tag 10002 to app "DEFAULT" 
*Mar  1 15:35:53.608: //44/xxxxxxxxxxxx/SSAPP:-1:-1/sess_appl: ev(24=CC_EV_CALL_SETUP_IND), cid(44), disp(0)
*Mar  1 15:35:53.608: //44/xxxxxxxxxxxx/SSAPP:-1:-1/sess_appl: ev(SSA_EV_CALL_SETUP_IND), cid(44), disp(0)
*Mar  1 15:35:53.608: //44/xxxxxxxxxxxx/SSAPP:-1:-1/ssaCallSetupInd:

The next line shows CallEntry ID in hexadecimal form, 0x2C (44 in decimal). The CallID and GUID numbers have been identified. The incoming dial-peer is 10002.

*Mar  1 15:35:53.608: //44/xxxxxxxxxxxx/CCAPI/ccCallSetContext: (callID=0x2C, context=0x634A430C) 
*Mar  1 15:35:53.608: //44/45F2AAE28044/SSAPP:10002:-1/ssaCallSetupInd: cid(44), st(SSA_CS_MAPPING),oldst(0), ev(24)ev->e.evCallSetupInd.nCallInfo.finalDestFlag
 = 1 
*Mar  1 15:35:53.608: //44/45F2AAE28044/SSAPP:10002:-1/ssaCallSetupInd: src route label=, tgt route label= tg_label_flag 0x0
*Mar  1 15:35:53.608: //44/45F2AAE28044/SSAPP:10002:-1/ssaCallSetupInd: finalDest cllng(55555), clled(34999) tgt_route_label()tg_label_flag 0x0
*Mar  1 15:35:53.612: //44/45F2AAE28044/SSAPP:10002:-1/ssaCallSetupInd: cid(44),
 st(SSA_CS_CALL_SETTING),oldst(0), ev(24)dpMatchPeersMoreArg result= 0

For CallEntry ID 44, two dial-peer tags (10001 and 20002) were matched with called number 34999.

*Mar  1 15:35:53.612: //44/45F2AAE28044/SSAPP:10002:-1/ssaDebugPeers: ssaSetupPe
er cid(44) peer list: tag(10001) called number (34999) tag(20002) called number
(34999) 
*Mar  1 15:35:53.612: //44/45F2AAE28044/SSAPP:10002:-1/ssaSetupPeer: dialpeer tags in rotary= 10001  20002

The next line shows that 5 digits were matched for this dial peer and no prefix was added. The encapType (2) entry indicates a VoIP call.

*Mar  1 15:35:53.612: //44/45F2AAE28044/SSAPP:10002:-1/ssaSetupPeer: cid(44), de
stPat(34999), matched(5), prefix(), peer(637B0984), peer->encapType (2)
*Mar  1 15:35:53.612: //-1/xxxxxxxxxxxx/CCAPI/cc_can_gateway: Call legs: In=6, O
ut=1

The next line shows the voice gateway sending out a call-proceeding message to the incoming call leg with progress indicator of 0x0.

*Mar  1 15:35:53.612: //44/xxxxxxxxxxxx/CCAPI/ccCallProceeding: (callID=0x2C, pr
og_ind=0x0) 

The next line shows the voice gateway sending out the call-setup request to the outgoing call leg. The dial-peer is 10001 with the incoming CallEntry ID being 0x2C.

*Mar  1 15:35:53.612: //44/xxxxxxxxxxxx/CCAPI/ccCallSetupRequest: (Inbound call
= 0x2C, outbound peer =10001, dest=,
        params=0x63085D80 mode=0, *callID=0x63086314, prog_ind = 0callingIE_pres
ent 1) 
*Mar  1 15:35:53.612: //44/45F2AAE28044/CCAPI/ccCallSetupRequest:
*Mar  1 15:35:53.612: ccCallSetupRequest numbering_type 0x80 
*Mar  1 15:35:53.612: //44/45F2AAE28044/CCAPI/ccCallSetupRequest:
*Mar  1 15:35:53.616: ccCallSetupRequest: calling number is:55555
*Mar  1 15:35:53.616: //44/45F2AAE28044/CCAPI/ccCallSetupRequest: calling oct3a
is:0x0
*Mar  1 15:35:53.616: //-1/xxxxxxxxxxxx/CCAPI/ccCheckClipClir:
*Mar  1 15:35:53.616: ccCheckClipClir: calling number is: "55555", calling oct3a
 is: 0x0
*Mar  1 15:35:53.616: //-1/xxxxxxxxxxxx/CCAPI/ccCheckClipClir:
*Mar  1 15:35:53.616: Calling Party number is User Provided
*Mar  1 15:35:53.616: //-1/xxxxxxxxxxxx/CCAPI/ccCheckClipClir:
*Mar  1 15:35:53.616: Leaving ccCheckClipClir
  calling number is: "55555"
  calling oct3 is:  0x80
  calling oct3a is: 0x0
*Mar  1 15:35:53.616: //44/45F2AAE28044/CCAPI/ccCallSetupRequest: after ccCheckC
lipClir - calling oct3a is:0x0

The next line shows that all digits are passed.

*Mar  1 15:35:53.616: //44/45F2AAE28044/CCAPI/ccCallSetupRequest: dest pattern 3
4999, called 34999, digit_strip 0 
*Mar  1 15:35:53.616: //44/45F2AAE28044/CCAPI/ccCallSetupRequest:
*Mar  1 15:35:53.616: callingNumber=55555, calledNumber=34999, redirectNumber= d
isplay_info= calling_oct3a=0
*Mar  1 15:35:53.616: accountNumber=, finalDestFlag=1,
guid=45f2.aae2.1571.11cc.8044.95f5.fabb.6b0f
*Mar  1 15:35:53.616: peer_tag=10001
*Mar  1 15:35:53.616: //-1/xxxxxxxxxxxx/CCAPI/cc_api_display_ie_subfields:
*Mar  1 15:35:53.616: ccCallSetupRequest:
*Mar  1 15:35:53.616:  cisco-username=
*Mar  1 15:35:53.616: ----- ccCallInfo IE subfields -----
*Mar  1 15:35:53.616:  cisco-ani=55555
*Mar  1 15:35:53.616:  cisco-anitype=0
*Mar  1 15:35:53.616:  cisco-aniplan=0
*Mar  1 15:35:53.616:  cisco-anipi=0
*Mar  1 15:35:53.616:  cisco-anisi=0
*Mar  1 15:35:53.620:  dest=34999
*Mar  1 15:35:53.620:  cisco-desttype=0
*Mar  1 15:35:53.620:  cisco-destplan=0
*Mar  1 15:35:53.620:  cisco-rdn=
*Mar  1 15:35:53.620:  cisco-rdntype=-1
*Mar  1 15:35:53.620:  cisco-rdnplan=-1
*Mar  1 15:35:53.620:  cisco-rdnpi=-1
*Mar  1 15:35:53.620:  cisco-rdnsi=-1
*Mar  1 15:35:53.620:  cisco-redirectreason=-1
*Mar  1 15:35:53.620: //-1/xxxxxxxxxxxx/CCAPI/ccIFCallSetupRequestPrivate: (vdbP
tr=0x62EC61A4, dest=, callParams={called=34999,called_oct3=0x80, calling=55555,calling_oct3=0x80, calling_oct3a= 0x0, calling_xlated=false,  subscriber_type_str
=RegularLine, fdest=1, voice_peer_tag=10001},mode=0x0)
*Mar  1 15:35:53.620: //-1/xxxxxxxxxxxx/CCAPI/ccIFCallSetupRequestPrivate:
*Mar  1 15:35:53.620: ccIFCallSetupRequestPrivate: src route label  tgt route label tg_label_flag 0x0
*Mar  1 15:35:53.620: //-1/xxxxxxxxxxxx/CCAPI/ccIFCallSetupRequestPrivate:  vdbPtr type = 1
*Mar  1 15:35:53.620: //-1/xxxxxxxxxxxx/CCAPI/ccIFCallSetupRequestPrivate:
*Mar  1 15:35:53.620: //-1/xxxxxxxxxxxx/CCAPI/ccIFCallSetupRequestPrivate: (vdbPtr=0x62EC61A4, dest=, callParams={called=34999, called_oct3 0x80,  calling=55555,calling_oct3 0x80, calling_oct3a 0x0, calling_xlated=false,  fdest=1, voice_pee
r_tag=10001}, mode=0x0, xltrc=-5)
*Mar  1 15:35:53.620: //-1/xxxxxxxxxxxx/CCAPI/ccIFCallSetupRequestPrivate:
In the next line, outgoing CallEntry ID 45 is bound to the same GUID 45F2AAE28044.
*Mar  1 15:35:53.620: //45/45F2AAE28044/CCAPI/cc_insert_call_entry: not incoming
 entry 
*Mar  1 15:35:53.620: //45/45F2AAE28044/CCAPI/cc_insert_call_entry: entry's incoming FALSE.
*Mar  1 15:35:53.620: //45/45F2AAE28044/CCAPI/cc_insert_call_entry: is_incoming
is FALSE
*Mar  1 15:35:53.624: //44/xxxxxxxxxxxx/CCAPI/ccSaveDialpeerTag: (callID=0x2C, dialpeer_tag=10001)
*Mar  1 15:35:53.624: //45/xxxxxxxxxxxx/CCAPI/ccCallSetContext: (callID=0x2D, context=0x634A537C) 0x2D (decimal 45 is the second call leg ID).
*Mar  1 15:35:53.624: //44/xxxxxxxxxxxx/CCAPI/ccCallReportDigits: (callID=0x2C,
enable=0x0)

The voice gateway informs the incoming call leg that digits were forwarded.

*Mar  1 15:35:53.624: //44/xxxxxxxxxxxx/CCAPI/cc_api_call_report_digits_done: (vdbPtr=0x637EC1E0, callID=0x2C, disp=0)
*Mar  1 15:35:53.624: //44/xxxxxxxxxxxx/SSAPP:-1:-1/sess_appl: ev(54=CC_EV_CALL_
REPORT_DIGITS_DONE), cid(44), disp(0)
*Mar  1 15:35:53.624: //44/45F2AAE28044/SS
Router#APP:10002:-1/ssaTraceSct: cid(44)st(SSA_CS_CALL_SETTING)ev(SSA_EV_CALL_RE
PORT_DIGITS_DONE)
oldst(SSA_CS_MAPPING)cfid(-1)csize(0)in(1)fDest(1)
*Mar  1 15:35:53.624: //44/45F2AAE28044/SSAPP:10002:-1/ssaTraceSct: -cid2(45)st2
(SSA_CS_CALL_SETTING)oldst2(SSA_CS_MAPPING)
*Mar  1 15:35:53.624: //44/45F2AAE28044/SSAPP:10002:-1/ssaDebugPeers: ssaReportDigitsDone cid(44) peer list: tag(20002) called number (34999)
*Mar  1 15:35:53.624: //44/45F2AAE28044/SSAPP:10002:-1/ssaReportDigitsDone: call
id=44 Reporting disabled.
*Mar  1 15:35:53.628: //-1/xxxxxxxxxxxx/CCAPI/cc_api_supported_data: data_mode=0x10082
*Mar  1 15:35:53.628: //45/xxxxxxxxxxxx/CCAPI/cc_api_get_ic_leg_obtained_numbers: callID=0x2D

The next two lines shows the IP address of the terminating gateway and that the terminating gateway is reached through Ethernet port 0/0.

*Mar  1 15:35:53.628: //-1/xxxxxxxxxxxx/CCAPI/cc_incr_if_call_volume: remote IP
is 171.69.85.111 
*Mar  1 15:35:53.632: //-1/xxxxxxxxxxxx/CCAPI/cc_incr_if_call_volume: hwidb is Ethernet0/0 
*Mar  1 15:35:53.632: //-1/xxxxxxxxxxxx/CCAPI/cc_incr_if_call_volume: create entry in list: 1
*Mar  1 15:35:53.636: //45/xxxxxxxxxxxx/CCAPI/ccTDUtilGetInstanceCount: For tagI
D[1] of callID[45]
*Mar  1 15:35:53.636: //45/45F2AAE28044/CCAPI/ccTDPvtProfileTableObjectAccessManager: No profileTable set for callID[45]
*Mar  1 15:35:53.636: //45/xxxxxxxxxxxx/CCAPI/ccTDUtilGetInstanceCount: For tagID[2] of callID[45]
*Mar  1 15:35:53.636: //45/45F2AAE28044/CCAPI/ccTDPvtProfileTableObjectAccessManager: No profileTable set for callID[45]

The next line shows that the voice gateway received a call proceeding message from the terminating gateway, and then the following line shows that the voice gateway received a call alert from the terminating gateway.

*Mar  1 15:35:53.740: //45/xxxxxxxxxxxx/CCAPI/cc_api_call_proceeding: (vdbPtr=0x62EC61A4, callID=0x2D,
      prog_ind=0x0) 
*Mar  1 15:35:53.740: //45/xxxxxxxxxxxx/CCAPI/cc_api_call_alert: (vdbPtr=0x62EC61A4, callID=0x2D, prog_ind=0x0, sig_ind=0x1) 
*Mar  1 15:35:53.744: //45/xxxxxxxxxxxx/SSAPP:-1:-1/sess_appl: ev(21=CC_EV_CALL_PROCEEDING), cid(45), disp(0)
*Mar  1 15:35:53.744: //45/45F2AAE28044/SSAPP:0:-1/ssaTraceSct: cid(45)st(SSA_CS
_CALL_SETTING)ev(SSA_EV_CALL_PROCEEDING)
oldst(SSA_CS_MAPPING)cfid(-1)csize(0)in(0)fDest(0)
*Mar  1 15:35:53.744: //45/45F2AAE28044/SSAPP:0:-1/ssaTraceSct: -cid2(44)st2(SSA_CS_CALL_SETTING)oldst2(SSA_CS_CALL_SETTING)
*Mar  1 15:35:53.744: //45/45F2AAE28044/SSAPP:0:-1/ssaCallProc:
*Mar  1 15:35:53.744: //44/xxxxxxxxxxxx/CCAPI/ccGetDialpeerTag: (callID=0x2C)
*Mar  1 15:35:53.744: //45/45F2AAE28044/SSAPP:0:-1/ssaIgnore: cid(45), st(SSA_CS
_CALL_SETTING),oldst(1), ev(21)
*Mar  1 15:35:53.744: //45/xxxxxxxxxxxx/SSAPP:-1:-1/sess_appl: ev(7=CC_EV_CALL_ALERT), cid(45), disp(0)
*Mar  1 15:35:53.744: //45/45F2AAE28044/SSAPP:0:-1/ssaTraceSct: cid(45)st(SSA_CS
_CALL_SETTING)ev(SSA_EV_CALL_ALERT)
oldst(SSA_CS_CALL_SETTING)cfid(-1)csize(0)in(0)fDest(0)
*Mar  1 15:35:53.744: //45/45F2AAE28044/SSAPP:0:-1/ssaTraceSct: -cid2(44)st2(SSA
_CS_CALL_SETTING)oldst2(SSA_CS_CALL_SETTING)
*Mar  1 15:35:53.744: //44/45F2AAE28044/SSAPP:10002:-1/ssaAlert:
*Mar  1 15:35:53.744: //44/xxxxxxxxxxxx/CCAPI/ccGetDialpeerTag: (callID=0x2C)
Router#

The voice gateway forwarded a call alert to the originating gateway.

*Mar  1 15:35:53.744: //44/xxxxxxxxxxxx/CCAPI/ccCallAlert: (callID=0x2C, prog_ind=0x0, sig_ind=0x1) 
Router#

The phone is answered at the called number.

Router#!call answered 
Router#

The voice gateway receives a connect message from the terminating gateway.

*Mar  1 15:36:05.016: //45/xxxxxxxxxxxx/CCAPI/cc_api_call_connected: (vdbPtr=0x6
2EC61A4, callID=0x2D), prog_ind = 0 
*Mar  1 15:36:05.016: //45/45F2AAE28044/CCAPI/cc_api_call_connected: setting callEntry->connected to TRUE

The next line shows that the call accounting starts. The leg_type=False message means this is for an outgoing call. The line that follows shows that AAA accounting is not configured.

*Mar  1 15:36:05.016: //45/45F2AAE28044/CCAPI/cc_api_call_connected: calling accounting start for callID=45 leg_type=0 
*Mar  1 15:36:05.020: //45/xxxxxxxxxxxx/CCAPI/ccCallSetAAA_Accounting: callID=0x
2D, accounting=0 
*Mar  1 15:36:05.020: //45/xxxxxxxxxxxx/SSAPP:-1:-1/sess_appl: ev(8=CC_EV_CALL_CONNECTED), cid(45), disp(0)
*Mar  1 15:36:05.020: //45/45F2AAE28044/SSAPP:0:-1/ssaTraceSct: cid(45)st(SSA_CS
_ALERT_RCVD)ev(SSA_EV_CALL_CONNECTED)
oldst(SSA_CS_CALL_SETTING)cfid(-1)csize(0)in(0)fDest(0)
*Mar  1 15:36:05.020: //45/45F2AAE28044/SSAPP:0:-1/ssaTraceSct: -cid2(44)st2(SSA
_CS_ALERT_RCVD)oldst2(SSA_CS_CALL_SETTING)
*Mar  1 15:36:05.020: //45/45F2AAE28044/SSAPP:0:-1/ssaConnect:
*Mar  1 15:36:05.020: //44/xxxxxxxxxxxx/CCAPI/ccGetDialpeerTag: (callID=0x2C)

The next lines show a conference being set up between the two call legs 0x2C and 0x2D. Bridge complete messages are sent to both the terminating and originating gateways.

*Mar  1 15:36:05.020: //44/xxxxxxxxxxxx/CCAPI/ccConferenceCreate: (confID=0x6308
6424, callID1=0x2C, callID2=0x2D, tag=0x0) 
*Mar  1 15:36:05.020: //45/xxxxxxxxxxxx/CCAPI/cc_api_bridge_done: (confID=0x15,
srcIF=0x62EC61A4, srcCallID=0x2D, dstCallID=0x2C, disposition=0, tag=0x0)
*Mar  1 15:36:05.024: //44/xxxxxxxxxxxx/CCAPI/cc_api_bridge_done: (confID=0x15,
srcIF=0x637EC1E0, srcCallID=0x2C, dstCallID=0x2D, disposition=0, tag=0x0)

Here, the voice gateway sets up negotiating capability with the originating telephony leg.

*Mar  1 15:36:05.024: //44/xxxxxxxxxxxx/CCAPI/cc_api_caps_ind: (dstVdbPtr=0x62EC
61A4, dstCallId=0x2D, srcCallId=0x2C,
     caps={codec=0x2887F, fax_rate=0xBF, vad=0x3, modem=0x2
           codec_bytes=0, signal_type=3})
*Mar  1 15:36:05.024: //44/xxxxxxxxxxxx/CCAPI/cc_api_caps_ind: (Playout: mode 0,
 initial 60,min 40, max 300) 
*Mar  1 15:36:05.024: //44/xxxxxxxxxxxx/SSAPP:-1:-1/sess_appl: ev(29=CC_EV_CONF_
CREATE_DONE), cid(44), disp(0)
*Mar  1 15:36:05.024: //44/45F2AAE28044/SSAPP:10002:21/ssaTraceSct: cid(44)st(SSA_CS_CONFERENCING)ev(SSA_EV_CONF_CREATE_DONE)
oldst(SSA_CS_CALL_SETTING)cfid(21)csize(2)in(1)fDest(1)
*Mar  1 15:36:05.024: //44/45F2AAE28044/SSAPP:10002:21/ssaTraceSct: -cid2(45)st2
(SSA_CS_CONFERENCING)oldst2(SSA_CS_ALERT_RCVD)
*Mar  1 15:36:05.024: //44/45F2AAE28044/SSAPP:10002:21/ssaConfCreateDone:
*Mar  1 15:36:05.024: //44/xxxxxxxxxxxx/CCAPI/ccCallConnect: (callID=0x2C), prog
_ind = 0
*Mar  1 15:36:05.024: //44/45F2AAE28044/CCAPI/ccCallConnect: setting callEntry->
connected to TRUE
*Mar  1 15:36:05.024: //44/45F2AAE28044/SSAPP:10002:21/ssaDebugPeers: ssaFlushPeerTagQueue cid(44) peer list: tag(20002) called number (34999)
*Mar  1 15:36:05.028: //-1/xxxxxxxxxxxx/CCAPI/cc_process_notify_bridge_done: (event=0x63067FC0)

The voice gateway sets up negotiating capability with the terminating VoIP leg.

*Mar  1 15:36:05.028: //45/xxxxxxxxxxxx/CCAPI/cc_api_caps_ind: (dstVdbPtr=0x637E
C1E0, dstCallId=0x2C, srcCallId=0x2D,
     caps={codec=0x4, fax_rate=0x2, vad=0x2, modem=0x0
           codec_bytes=20, signal_type=2})
*Mar  1 15:36:05.028: //45/xxxxxxxxxxxx/CCAPI/
cc_api_caps_ind:
 (Playout: mode 0,
 initial 60,min 40, max 300) 

The capabilities are acknowledged for both call legs.

*Mar  1 15:36:05.028: //45/xxxxxxxxxxxx/CCAPI/cc_api_caps_ack: (dstVdbPtr=0x637E
C1E0, dstCallId=0x2C, srcCallId=0x2D,
     caps={codec=0x4, fax_rate=0x2, vad=0x2, modem=0x0
           codec_bytes=20, signal_type=2, seq_num_start=2944})
*Mar  1 15:36:05.028: //44/xxxxxxxxxxxx/CCAPI/cc_api_caps_ack: (dstVdbPtr=0x62EC
61A4, dstCallId=0x2D, srcCallId=0x2C,
     caps={codec=0x4, fax_rate=0x2, vad=0x2, modem=0x0
           codec_bytes=20, signal_type=2, seq_num_start=2944})
*Mar  1 15:36:05.032: //44/xxxxxxxxxxxx/CCAPI/cc_api_voice_mode_event: callID=0x2C
*Mar  1 15:36:05.032: //44/45F2AAE28044/CCAPI/cc_api_voice_mode_event: Call Pointer =634A430C
*Mar  1 15:36:05.032: //44/xxxxxxxxxxxx/SSAPP:-1:-1/sess_appl: ev(52=CC_EV_VOICE
_MODE_DONE), cid(44), disp(0)
*Mar  1 15:36:05.032: //44/45F2AAE28044/SSAPP:10002:21/ssaTraceSct:
Router#
Router# cid(44)st(SSA_CS_ACTIVE)ev(SSA_EV_VOICE_MODE_DONE)
oldst(SSA_CS_CONFERENCING)cfid(21)csize(2)in(1)fDest(1)
*Mar  1 15:36:05.032: //44/45F2AAE28044/SSAPP:10002:21/ssaTraceSct: -cid2(45)st2
(SSA_CS_ACTIVE)oldst2(SSA_CS_ALERT_RCVD)
*Mar  1 15:36:05.032: //44/45F2AAE28044/SSAPP:10002:21/ssaIgnore: cid(44), st(SS
A_CS_ACTIVE),oldst(5), ev(52)
Router#
Router#! digit punched
Router#

The phone at the terminating gateway enters digit1.

*Mar  1 15:36:11.204: //45/xxxxxxxxxxxx/CCAPI/cc_api_call_digit_begin: (dstVdbPtr=0x637EC1E0, dstCallId=0x2C, srcCallId=0x2D,
    digit=1, digit_begin_flags=0x0, rtp_timestamp=0x0
    rtp_expiration=0x0, dest_mask=0x2)
*Mar  1 15:36:11.504: //45/xxxxxxxxxxxx/CCAPI/cc_api_call_digit_end: (dstVdbPtr=
0x637EC1E0, dstCallId=0x2C, srcCallId=0x2D,
    digit=1,duration=300,xruleCallingTag=0,xruleCalledTag=0, dest_mask=0x2), digit_tone_mode=0

The phone at the terminating gateway enters digit 2.

*Mar  1 15:36:11.604: //45/xxxxxxxxxxxx/CCAPI/cc_api_call_digit_begin: (dstVdbPt
r=0x637EC1E0, dstCallId=0x2C, srcCallId=0x2D,
    digit=2, digit_begin_flags=0x0, rtp_timestamp=0x0
    rtp_expiration=0x0, dest_mask=0x2)
*Mar  1 15:36:11.904: //45/xxxxxxxxxxxx/CCAPI/cc_api_call_digit_end: (dstVdbPtr=
0x637EC1E0, dstCallId=0x2C, srcCallId=0x2D,
    digit=2,duration=300,xruleCallingTag=0,xruleCalledTag=0, dest_mask=0x2), digit_tone_mode=0
Router#
Router#
*Mar  1 15:36:14.476: //-1/xxxxxxxxxxxx/CCAPI/cc_handle_periodic_timer: Calling
the callback, ccTimerctx - 0x628B6330
*Mar  1 15:36:14.476: //-1/xxxxxxxxxxxx/CCAPI/ccTimerStart: ccTimerctx - 0x628B6330
Router#
Router# !call hung up  The user at the terminating gateway hangs up the call.
Router#

The voice gateway receives a disconnect message from the terminating gateway. The cause code is 0x10 which is normal call clearing.

*Mar  1 15:36:22.916: //45/xxxxxxxxxxxx/CCAPI/cc_api_call_disconnected: (vdbPtr=
0x62EC61A4, callID=0x2D, cause=0x10)
*Mar  1 15:36:22.920: //45/xxxxxxxxxxxx/SSAPP:-1:-1/sess_appl: ev(11=CC_EV_CALL_
DISCONNECTED), cid(45), disp(0)
*Mar  1 15:36:22.920: //45/45F2AAE28044/SSAPP:0:21/ssaTraceSct: cid(45)st(SSA_CS
_ACTIVE)ev(SSA_EV_CALL_DISCONNECTED)
oldst(SSA_CS_ALERT_RCVD)cfid(21)csize(2)in(0)fDest(0)
*Mar  1 15:36:22.920: //45/45F2AAE28044/SSAPP:0:21/ssaTraceSct: -cid2(44)st2(SSA
_CS_ACTIVE)oldst2(SSA_CS_ACTIVE)
*Mar  1 15:36:22.920: ssa: Disconnected cid(45) state(5) cause(0x10)

The voice gateway begins tearing down the conference and dropping the bridge.

*Mar  1 15:36:22.920: //-1/xxxxxxxxxxxx/CCAPI/ccConferenceDestroy: (confID=0x15,
 tag=0x0) 
*Mar  1 15:36:22.920: //45/xxxxxxxxxxxx/CCAPI/cc_api_bridge_drop_done: (confID=0
x15, srcIF=0x62EC61A4, srcCallID=0x2D, dstCallID=0x2C, disposition=0 tag=0x0)
*Mar  1 15:36:22.920: //44/xxxxxxxxxxxx/CCAPI/cc_api_bridge_drop_done: (confID=0
x15, srcIF=0x637EC1E0, srcCallID=0x2C, dstCallID=0x2D, disposition=0 tag=0x0)
*Mar  1 15:36:22.924: //44/xxxxxxxxxxxx/SSAPP:-1:-1/sess_appl: ev(30=CC_EV_CONF_
DESTROY_DONE), cid(44), disp(0)
*Mar  1 15:36:22.924: //44/45F2AAE28044/SSAPP:10002:21/ssaTraceSct: cid(44)st(SSA_CS_CONF_DESTROYING)ev(SSA_EV_CONF_DESTROY_DONE)
oldst(SSA_CS_ACTIVE)cfid(21)csize(2)in(1)fDest(1)
*Mar  1 15:36:22.924: //44/45F2AAE28044/SSAPP:10002:21/ssaTraceSct: -cid2(45)st2
(SSA_CS_CONF_DESTROYING)oldst2(SSA_CS_ACTIVE)
*Mar  1 15:36:22.924: //45/45F2AAE28044/SSAPP:0:-1/ssaConfDestroyDone:
*Mar  1 15:36:22.924: //44/xxxxxxxxxxxx/CCAPI/ccCallDisconnect: (callID=0x2C, cause=0x10 tag=0x0)

The voice gateway stops call accounting on the incoming call, indicated by the leg_type=True message. The cause code is then set for the originating leg.

*Mar  1 15:36:22.924: //44/45F2AAE28044/CCAPI/ccCallDisconnect: calling accounting start for callID=44 leg_type=1 
*Mar  1 15:36:22.924: //44/45F2AAE28044/CCAPI/ccCallDisconnect: existing_cause =
 0x0, new_cause = 0x10 
*Mar  1 15:36:22.924: //44/xxxxxxxxxxxx/CCAPI/cc_api_get_transfer_info: (callID=0x2C)
*Mar  1 15:36:22.924: //45/xxxxxxxxxxxx/CCAPI/ccCallDisconnect: (callID=0x2D, cause=0x10 tag=0x0)

The voice gateway stops call accounting for the outgoing call, indicated by the leg_type=False message. The cause code is verified for the terminating leg.

*Mar  1 15:36:22.924: //45/45F2AAE28044/CCAPI/ccCallDisconnect: calling accounting start for callID=45 leg_type=0
*Mar  1 15:36:22.924: //45/45F2AAE28044/CCAPI/ccCallDisconnect: existing_cause =
 0x10, new_cause = 0x10 
*Mar  1 15:36:22.924: //45/45F2AAE28044/CCAPI/ccCallDisconnect: using the existing_cause 0x10
*Mar  1 15:36:22.928: //45/xxxxxxxxxxxx/CCAPI/cc_api_get_transfer_info: (callID=0x2D)
*Mar  1 15:36:22.932: //-1/xxxxxxxxxxxx/CCAPI/cc_api_icpif: expect factor = 0
*Mar  1 15:36:22.932: //-1/xxxxxxxxxxxx/CCAPI/g113_calculate_impairment: (delay=79,
      loss=0), Io=0 Iq=0 Idte=0 Idd=0 Ie=10 Itot=10
*Mar  1 15:36:22.932: //-1/xxxxxxxxxxxx/CCAPI/cc_decr_if_call_volume: the remote
 IP is 171.69.85.111
*Mar  1 15:36:22.932: //-1/xxxxxxxxxxxx/CCAPI/cc_decr_if_call_volume: hwidb is Ethernet0/0
*Mar  1 15:36:22.932: //-1/xxxxxxxxxxxx/CCAPI/cc_decr_if_call_volume: reduce callnum of entry: 0, voip: 0, mmoip: 0
*Mar  1 15:36:22.932: //-1/xxxxxxxxxxxx/CCAPI/cc_decr_if_call_volume: remove an entry
*Mar  1 15:36:22.932: //45/xxxxxxxxxxxx/CCAPI/cc_api_call_disconnect_done: (vdbPtr=0x62EC61A4, callID=0x2D, disp=0, tag=0x0)
*Mar  1 15:36:22.932: //45/45F2AAE28044/CCAPI/ccTDPvtProfileTableObjectAccessManager: No profileTable set for callID[45]
*Mar  1 15:36:22.936: //45/xxxxxxxxxxxx/CCAPI/ccTDUtilGetDataByRef: No tdObject
found in profileTable for tagID[6] of callID[45]
*Mar  1 15:36:22.936: //45/45F2AAE28044/CCAPI/cc_delete_call_entry: not incoming
 entry
*Mar  1 15:36:22.936: //45/45F2AAE28044/CCAPI/cc_delete_call_entry: entry's incoming FALSE.
*Mar  1 15:36:22.936: //45/45F2AAE28044/CCAPI/cc_delete_call_entry: is_incoming
is FALSE
*Mar  1 15:36:22.940: //45/xxxxxxxxxxxx/SSAPP:-1:-1/sess_appl: ev(12=CC_EV_CALL_
DISCONNECT_DONE), cid(45), disp(0)
*Mar  1 15:36:22.940: //45/45F2AAE28044/SSAPP:0:-1/ssaTraceSct: cid(45)st(SSA_CS
_DISCONNECTING)ev(SSA_EV_CALL_DISCONNECT_DONE)
oldst(SSA_CS_ACTIVE)cfid(-1)csize(2)in(0)fDest(0)
*Mar  1 15:36:22.940: //45/45F2AAE28044/SSAPP:0:-1/ssaTraceSct: -cid2(44)st2(SSA
_CS_DISCONNECTING)oldst2(SSA_CS_CONF_DESTROYING)
*Mar  1 15:36:22.940: //45/45F2AAE28044/SSAPP:0:-1/ssaDisconnectDone:
*Mar  1 15:36:22.940: //45/45F2AAE28044/SSAPP:0:-1/ssaAAA_CheckAccounting: accounting generation enabled
*Mar  1 15:36:22.940: //45/xxxxxxxxxxxx/CCAPI/ccCallSetAAA_Accounting: callID=0x2D, accounting=0
*Mar  1 15:36:22.944: //-1/xxxxxxxxxxxx/CCAPI/cc_decr_if_call_volume: not the VoIP or MMoIP
*Mar  1 15:36:22.948: //44/xxxxxxxxxxxx/CCAPI/cc_api_call_disconnect_done: (vdbPtr=0x637EC1E0, callID=0x2C, disp=0, tag=0x0)
*Mar  1 15:36:22.948: //44/45F2AAE28044/CCAPI/cc_delete_call_entry: ccFreeRawMsg
Info(0x6307595C)
*Mar  1 15:36:22.948: //44/45F2AAE28044/CCAPI/cc_delete_call_entry: Decrement call volume counter 1
*Mar  1 15:36:22.948: //44/45F2AAE28044/CCAPI/cc_delete_call_entry: current call volume: 0
*Mar  1 15:36:22.948: //44/45F2AAE28044/CCAPI/cc_delete_call_entry: entry's incoming TRUE.
*Mar  1 15:36:22.948: //44/45F2AAE28044/CCAPI/cc_delete_call_entry: is_incoming
is TRUE
*Mar  1 15:36:22.948: //44/45F2AAE28044/CCAPI/cc_delete_call_entry: Deleting profileTable[0x6380E11C]
*Mar  1 15:36:22.948: //-1/xxxxxxxxxxxx/CCAPI/ccTDDestructTDHashProfileTab: Destructor Profile Table (0x6380E11C)
*Mar  1 15:36:22.948: //-1/xxxxxxxxxxxx/CCAPI/ccTDDestructInstanceTDObject: tdObject[0x63401148] tagID[5]
*Mar  1 15:36:22.948: //-1/xxxxxxxxxxxx/CCAPI/ccTDDestructInstanceTDObject: tdObject[0x638BC1AC] tagID[6]
*Mar  1 15:36:22.956: //44/xxxxxxxxxxxx/SSAPP:-1:-1/sess_appl: ev(12=CC_EV_CALL_
DISCONNECT_DONE), cid(44), disp(0)
*Mar  1 15:36:22.956: //44/45F2AAE28044/SSAPP:10002:-1/ssaTraceSct: cid(44)st(SSA_CS_DISCONNECTING)ev(SSA_EV_CALL_DISCONNECT_DONE)
oldst(SSA_CS_CONF_DESTROYING)cfid(-1)csize(1)in(1)fDest(1)
Router#
*Mar  1 15:36:22.956: //44/45F2AAE28044/SSAPP:10002:-1/ssaDisconnectDone:

Examples

The following is sample output from the debug voip confmsp command:

Router# debug voip confmsp
 
CONFMSP debugging is on
.
.
.
00:06:44:confmsp_setup_request:callID (6),  
00:06:44:confmsp_setup_request:conf structure  (63DD27E4) created,  
00:06:44:confmsp_bridge:confID(4), callIDs(6,5) xmitFunc 61D46D4C, dstIF 64912880
 
00:06:44:confmsp_bridge:confID(4), callIDs(6,5) event queued 
00:06:44:confmsp_act_bridge: state = CONFMSP_STATE_SETUP, event=EV_CONFMSP_BRIDGING 
00:06:44:confmsp_act_bridge:codec 1, codec_bytes 160, vad 1
00:06:44:confmsp_act_bridge:codec 1, codec_bytes 160, vad 1
00:06:44:CNFSM:cur_container:confmsp container, cur_state:CONFMSP_STATE_SETUP,
event:EV_CONFMSP_BRIDGING, next_state:CONFMSP_STATE_CONNECT_CONFEREE
00:06:44:confmsp_get_dsmp_req_status:condition to be returned FALSE
00:06:44:confmsp_connect_response:found conf (63DD27E4) dsmp ret is 1
 
00:06:44:confmsp_act_bridge_success: state = CONFMSP_STATE_CONNECT_CONFEREE,
event=EV_CONFMSP_CNFRE_CONNECT_RESP_SUCCESS confmsp_caps_ind:context = 65241B34
 
00:06:44:CNFSM:cur_container:confmsp container, cur_state:CONFMSP_STATE_CONNECT_CONFEREE,
event:EV_CONFMSP_CNFRE_CONNECT_RESP_SUCCESS, next_state:CONFMSP_STATE_CONNECTED
00:06:44:confmsp_bridge:confID(5), callIDs(6,7) xmitFunc 61D46D4C, dstIF 64912880
 
00:06:44:confmsp_bridge:confID(5), callIDs(6,7) event queued 
00:06:44:confmsp_act_bridge: state = CONFMSP_STATE_SETUP, event=EV_CONFMSP_BRIDGING 
00:06:44:confmsp_act_bridge:codec 1, codec_bytes 160, vad 1
00:06:44:confmsp_act_bridge:codec 1, codec_bytes 160, vad 1
00:06:44:CNFSM:cur_container:confmsp container, cur_state:CONFMSP_STATE_SETUP,
event:EV_CONFMSP_BRIDGING, next_state:CONFMSP_STATE_CONNECT_CONFEREE
00:06:44:confmsp_get_dsmp_req_status:condition to be returned FALSE
00:06:44:confmsp_connect_response:found conf (6358A338) dsmp ret is 1
 
00:06:44:confmsp_act_bridge_success: state = CONFMSP_STATE_CONNECT_CONFEREE,
event=EV_CONFMSP_CNFRE_CONNECT_RESP_SUCCESS confmsp_caps_ind:context = 63588E70
 
00:06:44:CNFSM:cur_container:confmsp container, cur_state:CONFMSP_STATE_CONNECT_CONFEREE,
event:EV_CONFMSP_CNFRE_CONNECT_RESP_SUCCESS, next_state:CONFMSP_STATE_CONNECTED
00:06:44:confmsp_bridge:confID(6), callIDs(6,8) xmitFunc 61D46D4C, dstIF 64912880
 
00:06:44:confmsp_bridge:confID(6), callIDs(6,8) event queued 
00:06:44:confmsp_act_bridge: state = CONFMSP_STATE_SETUP, event=EV_CONFMSP_BRIDGING 
00:06:44:confmsp_act_bridge:codec 1, codec_bytes 160, vad 1
00:06:44:confmsp_act_bridge:codec 1, codec_bytes 160, vad 1
00:06:44:CNFSM:cur_container:confmsp container, cur_state:CONFMSP_STATE_SETUP,
event:EV_CONFMSP_BRIDGING, next_state:CONFMSP_STATE_CONNECT_CONFEREE
00:06:44:confmsp_get_dsmp_req_status:condition to be returned FALSE
00:06:44:confmsp_connect_response:found conf (6358CE50) dsmp ret is 1
 
00:06:44:confmsp_act_bridge_success: state = CONFMSP_STATE_CONNECT_CONFEREE,
event=EV_CONFMSP_CNFRE_CONNECT_RESP_SUCCESS confmsp_caps_ind:context = 63DD2524
 
00:06:44:CNFSM:cur_container:confmsp container, cur_state:CONFMSP_STATE_CONNECT_CONFEREE,
event:EV_CONFMSP_CNFRE_CONNECT_RESP_SUCCESS, next_state:CONFMSP_STATE_CONNECTED
00:07:28:confmsp_bdrop:confID(4), callIDs(6,5) 
00:07:28:confmsp_bdrop:confID(4), callIDs(6,5) event queued 
00:07:28:confmsp_act_bdrop: state = CONFMSP_STATE_CONNECTED, event=EV_CONFMSP_BRIDGEDROP 
00:07:28:CNFSM:cur_container:confmsp container, cur_state:CONFMSP_STATE_CONNECTED,
event:EV_CONFMSP_BRIDGEDROP, next_state:CONFMSP_STATE_DISCONNECT_CONFEREE
00:07:28:confmsp_get_dsmp_req_status:condition to be returned FALSE
00:07:28:confmsp_disconnect_response:found conf (63DD27E4)
 
00:07:28:confmsp_connect_response:found conf (63DD27E4) dsmp ret is 10
 
00:07:28:confmsp_act_bdrop_success: state = CONFMSP_STATE_DISCONNECT_CONFEREE,
event=EV_CONFMSP_CNFRE_DISCONNECT_RESP_SUCCESS 
00:07:28:CNFSM:cur_container:confmsp container,
cur_state:CONFMSP_STATE_DISCONNECT_CONFEREE,
event:EV_CONFMSP_CNFRE_DISCONNECT_RESP_SUCCESS, next_state:CONFMSP_STATE_BRIDGE_DROPPED
00:07:28:CNFSM:cur_container:confmsp container, cur_state:CONFMSP_STATE_BRIDGE_DROPPED,
event:CNFSM_LAMBDA_EVENT, next_state:CNFSM_NO_STATE_CHANGE
00:07:29:confmsp_bdrop:confID(6), callIDs(6,8) 
00:07:29:confmsp_bdrop:confID(6), callIDs(6,8) event queued 
00:07:29:confmsp_bdrop:confID(5), callIDs(6,7) 
00:07:29:confmsp_bdrop:confID(5), callIDs(6,7) event queued 
00:07:29:confmsp_act_bdrop: state = CONFMSP_STATE_CONNECTED, event=EV_CONFMSP_BRIDGEDROP 
00:07:29:CNFSM:cur_container:confmsp container, cur_state:CONFMSP_STATE_CONNECTED,
event:EV_CONFMSP_BRIDGEDROP, next_state:CONFMSP_STATE_DISCONNECT_CONFEREE
00:07:29:confmsp_get_dsmp_req_status:condition to be returned FALSE
00:07:29:confmsp_act_bdrop: state = CONFMSP_STATE_CONNECTED, event=EV_CONFMSP_BRIDGEDROP 
00:07:29:CNFSM:cur_container:confmsp container, cur_state:CONFMSP_STATE_CONNECTED,
event:EV_CONFMSP_BRIDGEDROP, next_state:CONFMSP_STATE_DISCONNECT_CONFEREE
00:07:29:confmsp_get_dsmp_req_status:condition to be returned FALSE
00:07:29:confmsp_disconnect_response:found conf (6358CE50)
 
00:07:29:confmsp_connect_response:found conf (6358CE50) dsmp ret is 10
 
00:07:29:confmsp_act_bdrop_success: state = CONFMSP_STATE_DISCONNECT_CONFEREE,
event=EV_CONFMSP_CNFRE_DISCONNECT_RESP_SUCCESS 
00:07:29:CNFSM:cur_container:confmsp container,
cur_state:CONFMSP_STATE_DISCONNECT_CONFEREE,
event:EV_CONFMSP_CNFRE_DISCONNECT_RESP_SUCCESS, next_state:CONFMSP_STATE_BRIDGE_DROPPED
00:07:29:confmsp_act_terminate: state = CONFMSP_STATE_BRIDGE_DROPPED,
event=CNFSM_LAMBDA_EVENT 
00:07:29:CNFSM:cur_container:confmsp container, cur_state:CONFMSP_STATE_BRIDGE_DROPPED,
event:CNFSM_LAMBDA_EVENT, next_state:CNFSM_NULL_STATE
00:07:29:confmsp_free_conf:freeing 6358CE50
 
00:07:29:confmsp_disconnect_response:found conf (6358A338)
 
00:07:29:confmsp_connect_response:found conf (6358A338) dsmp ret is 10
 
00:07:29:confmsp_act_bdrop_success: state = CONFMSP_STATE_DISCONNECT_CONFEREE,
event=EV_CONFMSP_CNFRE_DISCONNECT_RESP_SUCCESS 
00:07:29:CNFSM:cur_container:confmsp container,
cur_state:CONFMSP_STATE_DISCONNECT_CONFEREE,
event:EV_CONFMSP_CNFRE_DISCONNECT_RESP_SUCCESS, next_state:CONFMSP_STATE_BRIDGE_DROPPED
00:07:29:confmsp_act_terminate: state = CONFMSP_STATE_BRIDGE_DROPPED,
event=CNFSM_LAMBDA_EVENT 
00:07:29:CNFSM:cur_container:confmsp container, cur_state:CONFMSP_STATE_BRIDGE_DROPPED,
event:CNFSM_LAMBDA_EVENT, next_state:CNFSM_NULL_STATE
00:07:29:confmsp_free_conf:freeing 6358A338
 
00:07:29:confmsp_disconnect:callID (6) 
00:07:29:confmsp_disconnect:callID (6) event queued 
00:07:29:confmsp_act_disconnected: state = CONFMSP_STATE_BRIDGE_DROPPED,
event=EV_CONFMSP_DISCONNECT 
00:07:29:CNFSM:cur_container:confmsp container, cur_state:CONFMSP_STATE_BRIDGE_DROPPED,
event:EV_CONFMSP_DISCONNECT, next_state:CNFSM_NULL_STATE
00:07:29:confmsp_free_conf:freeing 63DD27E4

Examples

Following is sample output from the debug voip dcapi inoutcommand during call setup:

Router# debug voip dcapi inout
*Jan 27 16:26:23.957: dc_api_device_set_ringer_res: Set Ringer message success
*Jan 27 16:26:23.957: //-1/xxxxxxxxxxxx/CCAPI/dc_api_device_stop_tone_res:
 
*Jan 27 16:26:23.957: dc_api_device_stop_tone_res: Stop Tone message success
*Jan 27 16:26:23.957: //-1/xxxxxxxxxxxx/CCAPI/dc_api_media_open_rcv_channel:
 
*Jan 27 16:26:23.957: dc_api_media_open_rcv_channel: evt DC_EV_MEDIA_OPEN_RCV_CHNL is successsfully enqueued to app
*Jan 27 16:26:23.957: //-1/xxxxxxxxxxxx/CCAPI/dc_api_device_stop_tone_res:
 
*Jan 27 16:26:23.957: dc_api_device_stop_tone_res: Stop Tone message success
*Jan 27 16:26:23.957: //-1/xxxxxxxxxxxx/CCAPI/dc_api_device_call_state_res:
 
*Jan 27 16:26:23.957: dc_api_device_call_state_res: Call State message success
*Jan 27 16:26:23.957: //-1/xxxxxxxxxxxx/CCAPI/dc_api_device_call_info_res:
 

The table below describes the significant fields shown in the display.

Examples

The following examples show output for variations of the debug voip dialpeer command:

For these examples, the topology shown in the figure below is used.

Figure 2. Network Topology for debug voip dialpeer Output Examples

Examples

Router# debug voip dialpeer detail
 
voip dialpeer detail debugging is on
Router#

The following event identifies the called number:

*Apr 18 21:07:35.291: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeerCore:
   Match Rule=DP_MATCH_INCOMING_DNIS; Called Number=83103
*Apr 18 21:07:35.291: //-1/xxxxxxxxxxxx/DPM/dpMatchPeertype:
   Is Incoming=TRUE, Number Expansion=FALSE
*Apr 18 21:07:35.291: //-1/xxxxxxxxxxxx/DPM/dpMatchCore:
   Dial String=83103, Expanded String=83103, Calling Number=
   Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_SPEECH

The following event identifies the incoming dial peer and shows that it has been matched:

*Apr 18 21:07:35.291: //-1/xxxxxxxxxxxx/DPM/MatchNextPeer:
   Result=Success(0); Incoming Dial-peer=1 Is Matched
*Apr 18 21:07:35.291: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeerCore:
   Match Rule=DP_MATCH_INCOMING_DNIS; Called Number=83103
*Apr 18 21:07:35.291: //-1/xxxxxxxxxxxx/DPM/dpMatchPeertype:
   Is Incoming=TRUE, Number Expansion=FALSE
*Apr 18 21:07:35.291: //-1/xxxxxxxxxxxx/DPM/dpMatchCore:
   Dial String=83103, Expanded String=83103, Calling Number=
   Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_FAX
*Apr 18 21:07:35.291: //-1/xxxxxxxxxxxx/DPM/dpMatchCore:
   Result=-1
*Apr 18 21:07:35.291: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeerCore:
   Match Rule=DP_MATCH_ANSWER; Calling Number=4085550111
*Apr 18 21:07:35.291: //-1/xxxxxxxxxxxx/DPM/dpMatchPeertype:
   Is Incoming=TRUE, Number Expansion=FALSE
*Apr 18 21:07:35.291: //-1/xxxxxxxxxxxx/DPM/dpMatchCore:
   Dial String=, Expanded String=, Calling Number=4085550111T
   Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_FAX
*Apr 18 21:07:35.291: //-1/xxxxxxxxxxxx/DPM/dpMatchCore:
   Result=-1
*Apr 18 21:07:35.291: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeerCore:
   Match Rule=DP_MATCH_ORIGINATE; Calling Number=4085550111
*Apr 18 21:07:35.291: //-1/xxxxxxxxxxxx/DPM/dpMatchPeertype:
   Is Incoming=TRUE, Number Expansion=FALSE
*Apr 18 21:07:35.291: //-1/xxxxxxxxxxxx/DPM/dpMatchCore:
   Dial String=, Expanded String=, Calling Number=4085550111T
   Timeout=TRUE, Is Incoming=TRUE, Peer Info Type=DIALPEER_INFO_FAX
*Apr 18 21:07:35.295: //-1/xxxxxxxxxxxx/DPM/dpMatchCore:
   Result=-1

The following event shows the number expansion. This is the only dial peer debug command that shows the number expansion.

*Apr 18 21:07:35.295: //-1/xxxxxxxxxxxx/DPM/dpMatchCore:
   Dial String=83103, Expanded String=3600, Calling Number=
   Timeout=TRUE, Is Incoming=FALSE, Peer Info Type=DIALPEER_INFO_SPEECH

The next few lines show matching for the outgoing dial peer. These lines show the matching sequence if the first match is not available.

*Apr 18 21:07:35.295: //-1/xxxxxxxxxxxx/DPM/MatchNextPeer:
   Result=Success(0); Outgoing Dial-peer=3600 Is Matched
*Apr 18 21:07:35.295: //-1/xxxxxxxxxxxx/DPM/MatchNextPeer:
   Result=Success(0); Outgoing Dial-peer=36 Is Matched
*Apr 18 21:07:35.295: //-1/xxxxxxxxxxxx/DPM/MatchNextPeer:
   Result=Success(0); Outgoing Dial-peer=360 Is Matched
*Apr 18 21:07:35.295: //-1/23ED4B1B8010/DPM/dpMatchCore:
   Dial String=83103, Expanded String=3600, Calling Number=
   Timeout=TRUE, Is Incoming=FALSE, Peer Info Type=DIALPEER_INFO_SPEECH

Examples

Router# debug voip dialpeer inout
 
voip dialpeer inout debugging is on

The following event shows the calling and called numbers:

*May  1 19:32:11.731: //-1/6372E2598012/DPM/dpAssociateIncomingPeerCore:
   Calling Number=4085550111, Called Number=3600, Voice-Interface=0x0,
   Timeout=TRUE, Peer Encap Type=ENCAP_VOIP, Peer Search Type=PEER_TYPE_VOICE,
   Peer Info Type=DIALPEER_INFO_SPEECH

The following event shows the incoming dial peer:

*May  1 19:32:11.731: //-1/6372E2598012/DPM/dpAssociateIncomingPeerCore:
   Result=Success(0) after DP_MATCH_INCOMING_DNIS; Incoming Dial-peer=100
*May  1 19:32:11.731: //-1/6372E2598012/DPM/dpAssociateIncomingPeerCore:
   Calling Number=4085550111, Called Number=3600, Voice-Interface=0x0,
   Timeout=TRUE, Peer Encap Type=ENCAP_VOIP, Peer Search Type=PEER_TYPE_VOICE,
   Peer Info Type=DIALPEER_INFO_SPEECH
*May  1 19:32:11.731: //-1/6372E2598012/DPM/dpAssociateIncomingPeerCore:
   Result=Success(0) after DP_MATCH_INCOMING_DNIS; Incoming Dial-peer=100
*May  1 19:32:11.735: //-1/6372E2598012/DPM/dpMatchPeersCore:
   Calling Number=, Called Number=3600, Peer Info Type=DIALPEER_INFO_SPEECH
*May  1 19:32:11.735: //-1/6372E2598012/DPM/dpMatchPeersCore:
   Match Rule=DP_MATCH_DEST; Called Number=3600
*May  1 19:32:11.735: //-1/6372E2598012/DPM/dpMatchPeersCore:
   Result=Success(0) after DP_MATCH_DEST
*May  1 19:32:11.735: //-1/6372E2598012/DPM/dpMatchPeersMoreArg:
   Result=SUCCESS(0)

The following event shows the matched dial peers in the order of priority:

 
List of Matched Outgoing Dial-peer(s):
     1: Dial-peer Tag=3600
     2: Dial-peer Tag=36

Examples

The following examples show output for variations of the debug voip dsm command:

• debug voip dsm
• debug voip dsm
• debug voip dsm

For these examples, the topology shown in the figure below is used.

Figure 3. Network Topology for debug voip dsm Examples

Examples

Router# debug voip dsm session
 
DSP Stream Manager session debugging is on
*Apr 18 21:15:39.679: //-1/44A507668015/DSM:(2/1:23):0:0:0/dsm_start_basic_sm: .
*Apr 18 21:15:39.679: //-1/44A507668015/DSM:(2/1:23):0:8:4/dsm_start_basic_sm: dsp resource manager opened. ret 4
*Apr 18 21:15:39.679: //-1/44A507668015/DSM:(2/1:23):0:8:4/dsm_open_voice_and_set_params: .
*Apr 18 21:15:39.679: //-1/44A507668015/DSM:(2/1:23):0:8:4/set_playout_dmgr: playout default

The following event shows the echo cancellation setting:

*Apr 18 21:15:39.679: //-1/44A507668015/DSM:(2/1:23):0:8:4/dsm_dsp_echo_canceller_control: echo_cancel: 1
*Apr 18 21:15:39.695: //43/44A507668015/DSM:(2/1:23):0:8:4/dsp_stream_mgr_play_tone: .
*Apr 18 21:15:39.695: //43/44A507668015/DSM:(2/1:23):0:8:4/dsm_exec: [Feat SM: S:NONE B SM: S:S_DSM_INIT E:E_DSM_CC_GEN_TONE]
*Apr 18 21:15:39.695: //43/44A507668015/DSM:(2/1:23):0:8:4/dsm_act_gen_tone: Tone is not on, ignoring
*Apr 18 21:15:39.695: //43/44A507668015/DSM:(2/1:23):0:8:4/dsm_exec: [B SM: R:FSM_OK -> S:S_DSM_INIT]
*Apr 18 21:15:39.695: //43/44A507668015/DSM:(2/1:23):0:8:4/dsm_exec: [Feat SM: S:NONE B SM: S:S_DSM_INIT E:E_DSM_CC_BRIDGE]
*Apr 18 21:15:39.695: //43/44A507668015/DSM:(2/1:23):0:8:4/dsm_act_bridge: .

The following event indicates that modem relay is not supported on the specified port, which is port 2/1:23:

*Apr 18 21:15:39.695: //43/44A507668015/DSM:(2/1:23):0:8:4/dsm_act_bridge: Modem Relay NOT Supported on this end-point/voice-port.
disabling it...
*Apr 18 21:15:39.695: //43/44A507668015/DSM:(2/1:23):0:8:4/dsm_exec: [B SM: R:FSM_OK -> S:S_DSM_BRIDGING]
*Apr 18 21:15:39.695: //43/44A507668015/DSM:(2/1:23):0:8:4/dsm_exec: [Feat SM: S:NONE B SM: S:S_DSM_BRIDGING E:E_DSM_CC_CAPS_IND]
*Apr 18 21:15:39.695: //43/44A507668015/DSM:(2/1:23):0:8:4/dsm_act_caps_ind: .
*Apr 18 21:15:39.695: //43/44A507668015/DSM:(2/1:23):0:8:4/dsm_act_caps_ind: RTP PT:NTE[101],NSE[100],FaxInd[96],FaxAck[97],CiscoDT
121],FaxRelay[122],CASsig[123],ClearChan[125],PCMu[0],PCMa[8]Codec[4], TxDynamicPayload[0], RxDynamicPayload[0]
*Apr 18 21:15:39.695: //43/44A507668015/DSM:(2/1:23):0:8:4/dsm_act_caps_ind: dtmf relay: mode=1, codec=1
*Apr 18 21:15:39.695: //43/44A507668015/DSM:(2/1:23):0:8:4/dsm_act_caps_ind: Modem Relay NOT Supported on this end-point/voice-port
disabling it...
*Apr 18 21:15:39.695: //43/44A507668015/DSM:(2/1:23):0:8:4/dsm_act_caps_ind: passthrough: cap_modem_proto 4,cap_modem_codec 1, cap_
em_redundancy 0, payload 103, modem_relay 0, gw-xid 0
*Apr 18 21:15:39.695: //43/44A507668015/DSM:(2/1:23):0:8:4/dsm_debug_caps_encap: Encap 1, Vad 2, Codec 0x4, CodecBytes 20,
             FaxRate 1, FaxBytes 20, FaxNsf 0xAD0051
             SignalType 2
             DtmfRelay 1, Modem 2, SeqNumStart 0x5A1
*Apr 18 21:15:39.695: //43/44A507668015/DSM:(2/1:23):0:8:4/dsm_act_caps_ind: FORKING Parameters are forking mask: 0, simple_forking
dec_mask: 0, complex_forking_codec_mask 0
*Apr 18 21:15:39.695: //43/44A507668015/DSM:(2/1:23):0:8:4/dsm_act_caps_ind: playout: [ mode:1,init:60, min:40, max:200]. data_mode
*Apr 18 21:15:39.695: //43/44A507668015/DSM:(2/1:23):0:8:4/dsm_exec: [B SM: R:FSM_OK -> S:S_DSM_BRIDGING]
*Apr 18 21:15:39.695: //43/44A507668015/DSM:(2/1:23):0:8:4/dsm_exec: [Feat SM: S:NONE B SM: S:S_DSM_BRIDGING E:E_DSM_CC_CAPS_ACK]
*Apr 18 21:15:39.695: //43/44A507668015/DSM:(2/1:23):0:8:4/dsm_act_caps_ack: .
*Apr 18 21:15:39.695: //43/44A507668015/DSM:(2/1:23):0:8:4/dsm_act_caps_ack: passthrough: cap_modem_proto 4, cap_modem_codec 1, cap
dem_redundancy 0, payload 103, modem_relay 0, gw-xid 0
*Apr 18 21:15:39.695: //43/44A507668015/DSM:(2/1:23):0:8:4/dsm_act_caps_ack: Named Telephone Event payload rcv 101, tx 101
*Apr 18 21:15:39.695: //43/44A507668015/DSM:(2/1:23):0:8:4/dsm_switch_codec: Required codec is 16,  current dsp codec is -1
*Apr 18 21:15:39.695: //43/44A507668015/DSM:(2/1:23):0:8:4/dsm_switch_codec: codec = 16
*Apr 18 21:15:39.695: //43/44A507668015/DSM:(2/1:23):0:8:4/dsm_exec: [B SM: R:FSM_OK -> S:S_DSM_PENDING_CODEC_SWITCH]
*Apr 18 21:15:39.695: //43/44A507668015/DSM:(2/1:23):0:8:4/dsm_exec: [Feat SM: S:NONE B SM: S:S_DSM_PENDING_CODEC_SWITCH E:E_DSM_DS_PEND_SUCCESS]
*Apr 18 21:15:39.695: //43/44A507668015/DSM:(2/1:23):0:8:4/dsm_act_pend_codec_success: .
*Apr 18 21:15:39.695: //43/44A507668015/DSM:(2/1:23):0:8:4/dsm_open_voice_and_set_params: 
*Apr 18 21:15:39.695: //43/44A507668015/DSM:(2/1:23):0:8:4/set_playout_dmgr: playout default

The following event shows the echo cancellation setting:

*Apr 18 21:15:39.695: //43/44A507668015/DSM:(2/1:23):0:8:4/dsm_dsp_echo_canceller_control: echo_cancel: 1

The following event shows that the codec has changed:

*Apr 18 21:15:39.695: //43/44A507668015/DSM:(2/1:23):0:8:4/dsm_setup_stream_after_switch_codec_succ: codec change success
*Apr 18 21:15:39.695: //43/44A507668015/DSM:(2/1:23):0:8:4/dsm_add_fork: .
*Apr 18 21:15:39.695: //43/44A507668015/DSM:(2/1:23):0:8:4/dsm_update_fork_info: add_fork=0
*Apr 18 21:15:39.695: //43/44A507668015/DSM:(2/1:23):0:8:4/dsm_get_xmit_info_node: .
*Apr 18 21:15:39.695: //43/44A507668015/DSM:(2/1:23):0:8:4/dsm_update_fork_info:  xmit func is 61A7CDC4, context is 64F42DA0 peer_c
_id: 44, stream_count: 1, update_flag 0
*Apr 18 21:15:39.695: //43/44A507668015/DSM:(2/1:23):0:8:4/dsm_update_fork_info: The stream bit-mask is 1
*Apr 18 21:15:39.695: //43/44A507668015/DSM:(2/1:23):0:8:4/dsm_update_fork_info: The stream type is 0
*Apr 18 21:15:39.695: //43/44A507668015/DSM:(2/1:23):0:8:4/dsm_update_fork_info: The logical ssrc is 64 for stream 0
*Apr 18 21:15:39.699: //43/44A507668015/DSM:(2/1:23):0:8:4/dsm_update_stream_count:
*Apr 18 21:15:39.699:  g711_voice_count=0 g711_avt_count = 0
 g711_voice_avt_count = 0 complex_voice_count = 1
 complex_avt_count = 0 complex_voice_avt_count = 0
*Apr 18 21:15:39.699: //43/44A507668015/DSM:(2/1:23):0:8:4/dsm_exec: [B SM: R:FSM_OK -> S:S_DSM_BRIDGED]

Examples

Router# debug voip dsm stats
 
DSP Stream Manager stats debugging is on

The following event shows that the DSM is requesting statistics:

*May  1 19:40:09.775: //43/7EE6F84B8016/DSM:(4/0/0):-1:1:1/dsm_exec: [Feat SM: S:NONE B SM: S:S_DSM_BRIDGED E:E_DSM_CC_REQ_PACK_STAT]
*May  1 19:40:09.775: //43/7EE6F84B8016/DSM:(4/0/0):-1:1:1/dsm_act_cc_stats_req: .
*May  1 19:40:09.775: //43/7EE6F84B8016/DSM:(4/0/0):-1:1:1/dsm_act_cc_stats_req:  -1->dmgr=0x645461E0, stats_reqs=0

The following events show statistics for DSM transmission, reception, delay, and errors:

*May  1 19:40:09.775: //43/7EE6F84B8016/DSM:(4/0/0):-1:1:1/dsm_exec: [B SM: R:FSM_OK -> S:S_DSM_BRIDGED]
*May  1 19:40:09.775: //43/7EE6F84B8016/DSM:(4/0/0):-1:1:1/dsm_exec: [Feat SM: S:NONE B SM: S:S_DSM_BRIDGED E:E_DSM_DSP_GET_TX]
*May  1 19:40:09.775: //43/7EE6F84B8016/DSM:(4/0/0):-1:1:1/dsm_act_packet_stats_res: .
*May  1 19:40:09.775: //43/7EE6F84B8016/DSM:(4/0/0):-1:1:1/dsm_act_packet_stats_res:  -4->dmgr=0x645461E0,stats_reqs=3
*May  1 19:40:09.775: //43/7EE6F84B8016/DSM:(4/0/0):-1:1:1/dsm_exec: [B SM: R:FSM_OK -> S:S_DSM_BRIDGED]
*May  1 19:40:09.775: //43/7EE6F84B8016/DSM:(4/0/0):-1:1:1/dsm_exec: [Feat SM: S:NONE B SM: S:S_DSM_BRIDGED E:E_DSM_DSP_GET_RX]
*May  1 19:40:09.775: //43/7EE6F84B8016/DSM:(4/0/0):-1:1:1/dsm_act_packet_stats_res: .
*May  1 19:40:09.775: //43/7EE6F84B8016/DSM:(4/0/0):-1:1:1/dsm_act_packet_stats_res:  -4->dmgr=0x645461E0,stats_reqs=2
*May  1 19:40:09.775: //43/7EE6F84B8016/DSM:(4/0/0):-1:1:1/dsm_exec: [B SM: R:FSM_OK -> S:S_DSM_BRIDGED]
*May  1 19:40:09.775: //43/7EE6F84B8016/DSM:(4/0/0):-1:1:1/dsm_exec: [Feat SM: S:NONE B SM: S:S_DSM_BRIDGED E:E_DSM_DSP_GET_VP_DELAY]
*May  1 19:40:09.775: //43/7EE6F84B8016/DSM:(4/0/0):-1:1:1/dsm_act_packet_stats_res: .
*May  1 19:40:09.775: //43/7EE6F84B8016/DSM:(4/0/0):-1:1:1/dsm_act_packet_stats_res:  -4->dmgr=0x645461E0,stats_reqs=1
*May  1 19:40:09.775: //43/7EE6F84B8016/DSM:(4/0/0):-1:1:1/dsm_exec: [B SM: R:FSM_OK -> S:S_DSM_BRIDGED]
*May  1 19:40:09.775: //43/7EE6F84B8016/DSM:(4/0/0):-1:1:1/dsm_exec: [Feat SM: S:NONE B SM: S:S_DSM_BRIDGED E:E_DSM_DSP_GET_VP_ERROR]
*May  1 19:40:09.775: //43/7EE6F84B8016/DSM:(4/0/0):-1:1:1/dsm_act_packet_stats_res: .
Router#
*May  1 19:40:09.775: //43/7EE6F84B8016/DSM:(4/0/0):-1:1:1/dsm_act_packet_stats_res:  -4->dmgr=0x645461E0,stats_reqs=0

Examples

The following is sample output from the debug voip dsm command, with Cisco IOS Release 12.3(14)T software, when a VoIP call is in transition to the connected state:

Router# debug voip dsm
 
*Jun  8 20:10:33.205: //28/6F1FA7868003/DSM:(2/0:23):-1/dsp_stream_mgr_create: .
*Jun  8 20:10:33.209: //28/6F1FA7868003/DSM:(2/0:23):-1/set_echo_canceller_data: echo_cancel: 1
*Jun  8 20:10:33.209: //28/6F1FA7868003/DSM:(2/0:23):-1/set_echo_canceller_data: echo_flags: 55, echo_len: 512
*Jun  8 20:10:33.217: //28/6F1FA7868003/DSM:(2/0:23):-1/dsmp_dsmapi_reserve_resource_cb: .
*Jun  8 20:10:33.217: //28/6F1FA7868003/DSM:(2/0:23):-1/dsp_stream_mgr_set_elog_enable: .
*Jun  8 20:10:33.477: //28/6F1FA7868003/DSM:(2/0:23):-1/dsp_stream_mgr_reinit_platform_info: .
*Jun  8 20:10:33.477: //28/6F1FA7868003/DSM:(2/0:23):-1/dsmp_dsmapi_reserve_resource_cb: .
*Jun  8 20:10:33.485: //28/6F1FA7868003/DSM:(2/0:23):-1/dsp_stream_mgr_bridge: .
*Jun  8 20:10:33.485: //28/6F1FA7868003/DSM:(2/0:23):-1/dsp_stream_mgr_bridge: 
*Jun  8 20:10:33.485:  dsp_stream_mgr_bridge, src_call_id 28, dst_call_id 27
*Jun  8 20:10:33.485: //28/6F1FA7868003/DSM:(2/0:23):-1/dsp_stream_mgr_bridge: creating packet streams
*Jun  8 20:10:33.489: //28/6F1FA7868003/DSM:(2/0:23):-1/dsm_insert_conn_array_entry: dmgr->connArr.count = 2
*Jun  8 20:10:33.489: //28/6F1FA7868003/DSM:(2/0:23):-1/dsp_stream_mgr_do_caps_ind: .
*Jun  8 20:10:33.493: //28/6F1FA7868003/DSM:(2/0:23):-1/dsp_stream_mgr_cap_ind_ack: src_call_id = 28, dst_call_id = 27, is_cap_ack = 1
*Jun  8 20:10:33.493: //28/6F1FA7868003/DSM:(2/0:23):-1/dsp_stream_mgr_cap_ind_ack: src_call_id = 28, dst_call_id = 27, is_cap_ack = 0
*Jun  8 20:10:33.493: //28/6F1FA7868003/DSM:(2/0:23):-1/dsm_caps_ind_negotiation: Caps in caps indication:
*Jun  8 20:10:33.497: //28/6F1FA7868003/DSM:(2/0:23):-1/dsm_caps_dump: playout: [ mode:1,init:60, min:40, max:250]. data_mode:0
*Jun  8 20:10:33.497: //28/6F1FA7868003/DSM:(2/0:23):-1/dsm_caps_dump: RTP PT:NTE[101],NSE[100],FaxInd[96],FaxAck[97],CiscoDTMF[121],FaxRelay[122],CASsig[123],ClearChan[125],PCMu[0],PCMa[8]Codec[4], TxDynamicPayload[0], RxDynamicPayload[0]
*Jun  8 20:10:33.497: //28/6F1FA7868003/DSM:(2/0:23):-1/dsm_caps_dump: passthrough: cap_modem_proto 4,cap_modem_codec 1, cap_modem_redundancy 1, payload 100, modem_relay 0, gw-xid 0
*Jun  8 20:10:33.497: //28/6F1FA7868003/DSM:(2/0:23):-1/dsm_debug_caps_encap: Encap 1, Vad 2, Codec 0x4, CodecBytes 20, 
             FaxRate 2, FaxBytes 20, FaxNsf 0xAD0051 
             SignalType 2
             DtmfRelay 1, Modem 2, SeqNumStart 0x0
*Jun  8 20:10:33.497: //28/6F1FA7868003/DSM:(2/0:23):-1/dsm_caps_ind_negotiation: Caps after caps negotiation:
*Jun  8 20:10:33.497: //28/6F1FA7868003/DSM:(2/0:23):-1/dsm_caps_dump: playout: [ mode:1,init:60, min:40, max:250]. data_mode:0
*Jun  8 20:10:33.497: //28/6F1FA7868003/DSM:(2/0:23):-1/dsm_caps_dump: RTP PT:NTE[101],NSE[100],FaxInd[96],FaxAck[97],CiscoDTMF[121],FaxRelay[122],CASsig[123],ClearChan[125],PCMu[0],PCMa[8]Codec[4], TxDynamicPayload[0], RxDynamicPayload[0]
*Jun  8 20:10:33.501: //28/6F1FA7868003/DSM:(2/0:23):-1/dsm_caps_dump: passthrough: cap_modem_proto 4,cap_modem_codec 1, cap_modem_redundancy 1, payload 100, modem_relay 0, gw-xid 0
*Jun  8 20:10:33.501: //28/6F1FA7868003/DSM:(2/0:23):-1/dsm_debug_caps_encap: Encap 1, Vad 2, Codec 0x4, CodecBytes 20, 
             FaxRate 2, FaxBytes 20, FaxNsf 0xAD0051 
             SignalType 2
             DtmfRelay 1, Modem 2, SeqNumStart 0x0
*Jun  8 20:10:33.501: //28/6F1FA7868003/DSM:(2/0:23):-1/dsp_stream_mgr_cap_ind_ack: packet streams already created during bridging
*Jun  8 20:10:33.501: //28/6F1FA7868003/DSM:(2/0:23):-1/dsm_caps_ind_negotiation: Caps in caps indication:
*Jun  8 20:10:33.501: //28/6F1FA7868003/DSM:(2/0:23):-1/dsm_caps_dump: playout: [ mode:1,init:60, min:40, max:250]. data_mode:0
*Jun  8 20:10:33.501: //28/6F1FA7868003/DSM:(2/0:23):-1/dsm_caps_dump: RTP PT:NTE[101],NSE[100],FaxInd[96],FaxAck[97],CiscoDTMF[121],FaxRelay[122],CASsig[123],ClearChan[125],PCMu[0],PCMa[8]Codec[4], TxDynamicPayload[0], RxDynamicPayload[0]
*Jun  8 20:10:33.505: //28/6F1FA7868003/DSM:(2/0:23):-1/dsm_caps_dump: passthrough: cap_modem_proto 4,cap_modem_codec 1, cap_modem_redundancy 1, payload 100, modem_relay 0, gw-xid 0
*Jun  8 20:10:33.505: //28/6F1FA7868003/DSM:(2/0:23):-1/dsm_debug_caps_encap: Encap 1, Vad 2, Codec 0x4, CodecBytes 20, 
             FaxRate 2, FaxBytes 20, FaxNsf 0xAD0051 
             SignalType 2
             DtmfRelay 1, Modem 2, SeqNumStart 0x0
*Jun  8 20:10:33.505: //28/6F1FA7868003/DSM:(2/0:23):-1/dsm_caps_ind_negotiation: Caps after caps negotiation:
*Jun  8 20:10:33.505: //28/6F1FA7868003/DSM:(2/0:23):-1/dsm_caps_dump: playout: [ mode:1,init:60, min:40, max:250]. data_mode:0
*Jun  8 20:10:33.505: //28/6F1FA7868003/DSM:(2/0:23):-1/dsm_caps_dump: RTP PT:NTE[101],NSE[100],FaxInd[96],FaxAck[97],CiscoDTMF[121],FaxRelay[122],CASsig[123],ClearChan[125],PCMu[0],PCMa[8]Codec[4], TxDynamicPayload[0], RxDynamicPayload[0]
*Jun  8 20:10:33.505: //28/6F1FA7868003/DSM:(2/0:23):-1/dsm_caps_dump: passthrough: cap_modem_proto 4,cap_modem_codec 1, cap_modem_redundancy 1, payload 100, modem_relay 0, gw-xid 0
*Jun  8 20:10:33.505: //28/6F1FA7868003/DSM:(2/0:23):-1/dsm_debug_caps_encap: Encap 1, Vad 2, Codec 0x4, CodecBytes 20, 
             FaxRate 2, FaxBytes 20, FaxNsf 0xAD0051 
             SignalType 2
             DtmfRelay 1, Modem 2, SeqNumStart 0x0
*Jun  8 20:10:33.509: //28/6F1FA7868003/DSM:(2/0:23):-1/dsmp_dsmapi_connect_cb: .
*Jun  8 20:10:36.229: //28/6F1FA7868003/DSM:(2/0:23):-1/dsp_stream_mgr_req_stats: .
*Jun  8 20:10:36.233: //28/6F1FA7868003/DSM:(2/0:23):-1/dsmp_dsmapi_stats_cb: .
*Jun  8 20:10:38.265: //28/6F1FA7868003/DSM:(2/0:23):-1/dsp_stream_mgr_req_stats: .
*Jun  8 20:10:38.269: //28/6F1FA7868003/DSM:(2/0:23):-1/dsmp_dsmapi_stats_cb: .
*Jun  8 20:10:43.481: //28/6F1FA7868003/DSM:(2/0:23):-1/dsp_stream_mgr_req_stats: .
*Jun  8 20:10:43.489: //28/6F1FA7868003/DSM:(2/0:23):-1/dsmp_dsmapi_stats_cb: .

The following is sample output from the debug voip dsm command, with Cisco IOS Release 12.3(14)T software, when a VoIP call is in transition from connected to the disconnected state:

Router# debug voip dsm
 
*Jun  8 20:12:14.701: //28/6F1FA7868003/DSM:(2/0:23):-1/dsp_stream_mgr_req_stats: .
*Jun  8 20:12:14.705: //28/6F1FA7868003/DSM:(2/0:23):-1/dsmp_dsmapi_stats_cb: .
*Jun  8 20:12:18.721: //28/6F1FA7868003/DSM:(2/0:23):-1/dsp_stream_mgr_bridge_drop: 
*Jun  8 20:12:18.721:  dsp_stream_mgr_bridge_drop, src_call_id 28, dst_call_id 27
*Jun  8 20:12:18.721: //28/6F1FA7868003/DSM:(2/0:23):-1/dsm_delete_conn_array_entry: dmgr->connArr.count = 0
*Jun  8 20:12:18.737: //28/6F1FA7868003/DSM:(2/0:23):-1/dsmp_dsmapi_stats_cb: .
*Jun  8 20:12:18.765: //28/6F1FA7868003/DSM:(2/0:23):-1/dsp_stream_mgr_destroy: .
*Jun  8 20:12:18.765: //28/6F1FA7868003/DSM:(2/0:23):-1/dsmapi_accept_modem_passthrough_session:  : dmgr: 6561C520, active sessions 0, max sessions: 16 rejected sessions till now: 0
*Jun  8 20:12:18.769: //28/6F1FA7868003/DSM:(2/0:23):-1/dsmp_dsmapi_reserve_resource_cb: .

Examples

The following is sample output from the debug voip dsmp command for transcoding call:

Router# debug voip dsmp
 
Syslog logging:enabled (11 messages dropped, 2 messages rate-limited,
                0 flushes, 0 overruns, xml disabled, filtering disabled)
    Console logging:disabled
    Monitor logging:level debugging, 0 messages logged, xml disabled,
                     filtering disabled
    Buffer logging:level debugging, 236 messages logged, xml disabled,
                    filtering disabled
    Logging Exception size (4096 bytes)
    Count and timestamp logging messages:disabled
    Trap logging:level informational, 25 message lines logged
 
Log Buffer (3000000 bytes):
 
00:10:18:dsmpAddStream::
00:10:18:dsmpAddStream::
00:10:18:dsmpAddStream::
00:10:18:dsmpAddStream::
00:10:18:dsmpConnectXcodeBinderReq
00:10:18:dsmp_process_event:
00:10:18:dsmp_process_event:evt->requestType = E_DSMP_CC_XCODE_REQ
00:10:18:dsmpxc_act_alloc_rsc::state = S_DSMPXC_INITIAL event = E_DSMP_CC_XCODE_REQ 
00:10:18:dsp_ret = 4 (if failed, cause = 0)
00:10:18:dsp_intf = 0x63DD21D8
00:10:18:dsmp_set_state_var:message to DSP
    successful,ret::4
00:10:18:CNFSM:cur_container:xcoder_container, cur_state:S_DSMPXC_INITIAL,
event:E_DSMP_CC_XCODE_REQ, next_state:S_DSMPXC_RSC_ALLOCING
00:10:18:dsmp_is_ret_succ::
00:10:18:dsmpxc_act_init_rsc::state = S_DSMPXC_RSC_ALLOCING event = CNFSM_LAMBDA_EVENT 
00:10:18:dsmp_set_state_var:message to DSP
    successful,ret::4
00:10:18:CNFSM:cur_container:xcoder_container, cur_state:S_DSMPXC_RSC_ALLOCING,
event:CNFSM_LAMBDA_EVENT, next_state:S_DSMPXC_RSC_INITING
00:10:18:dsmp_is_ret_succ::
00:10:18:dsmpxc_act_open_rsc::state = S_DSMPXC_RSC_INITING event = CNFSM_LAMBDA_EVENT 
00:10:18:dsmp_set_state_var:message to DSP
    successful,ret::4
00:10:18:CNFSM:cur_container:xcoder_container, cur_state:S_DSMPXC_RSC_INITING,
event:CNFSM_LAMBDA_EVENT, next_state:S_DSMPXC_RSC_OPENING
00:10:18:dsmp_is_ret_succ::
00:10:18:dsmpxc_act_program_rsc::state = S_DSMPXC_RSC_OPENING event = CNFSM_LAMBDA_EVENT 
00:10:18:dsmp_set_state_var:message to DSP
    successful,ret::4
00:10:18:CNFSM:cur_container:xcoder_container, cur_state:S_DSMPXC_RSC_OPENING,
event:CNFSM_LAMBDA_EVENT, next_state:S_DSMPXC_XCODE_PEND
00:10:18:CNFSM:new_container:xcoding_container
00:10:18:dsmp_is_ret_succ::
00:10:18:dsmpxc_act_succ_conn_req::state = S_DSMPXC_XCODE_PEND event = CNFSM_LAMBDA_EVENT 
00:10:18:CNFSM:cur_container:xcoding_container, cur_state:S_DSMPXC_XCODE_PEND,
event:CNFSM_LAMBDA_EVENT, next_state:S_DSMPXC_XCODE
00:10:18:no_stream_in_session
Router# clear log
Clear logging buffer [confirm]
Router#
Router# clear logsh logg 
 
Syslog logging:enabled (11 messages dropped, 2 messages rate-limited,
                0 flushes, 0 overruns, xml disabled, filtering disabled)
    Console logging:disabled
    Monitor logging:level debugging, 0 messages logged, xml disabled,
                     filtering disabled
    Buffer logging:level debugging, 274 messages logged, xml disabled,
                    filtering disabled
    Logging Exception size (4096 bytes)
    Count and timestamp logging messages:disabled
    Trap logging:level informational, 25 message lines logged
 
Log Buffer (3000000 bytes):
 
00:10:50:dsmpDeleteStream
00:10:50:dsmpDeleteStream
00:10:50:dsmpDeleteStream
00:10:50:dsmpDeleteStream
00:10:50:dsmp_process_event:
00:10:50:dsmp_process_event:evt->requestType = E_DSMP_CC_DELETE_STREAM
00:10:50:dsmpxc_act_delete_stream::state = S_DSMPXC_XCODE event = E_DSMP_CC_DELETE_STREAM 
00:10:50:CNFSM:cur_container:xcoding_container, cur_state:S_DSMPXC_XCODE,
event:E_DSMP_CC_DELETE_STREAM, next_state:CNFSM_NO_STATE_CHANGE
00:10:50:no_stream_in_session
00:10:50:dsmp_process_event:evt->requestType = E_DSMP_CC_DELETE_STREAM
00:10:50:dsmpxc_act_delete_stream::state = S_DSMPXC_XCODE event = E_DSMP_CC_DELETE_STREAM 
00:10:50:CNFSM:cur_container:xcoding_container, cur_state:S_DSMPXC_XCODE,
event:E_DSMP_CC_DELETE_STREAM, next_state:CNFSM_NO_STATE_CHANGE
00:10:50:no_stream_in_session
00:10:50:dsmp_process_event:evt->requestType = E_DSMP_CC_DELETE_STREAM
00:10:50:dsmpxc_act_delete_stream::state = S_DSMPXC_XCODE event = E_DSMP_CC_DELETE_STREAM 
00:10:50:CNFSM:cur_container:xcoding_container, cur_state:S_DSMPXC_XCODE,
event:E_DSMP_CC_DELETE_STREAM, next_state:CNFSM_NO_STATE_CHANGE
00:10:50:no_stream_in_session
00:10:50:dsmp_process_event:evt->requestType = E_DSMP_CC_DELETE_STREAM
00:10:50: dsmpxc_act_delete_stream::state = S_DSMPXC_XCODE event = E_DSMP_CC_DELETE_STREAM 
00:10:50:CNFSM:cur_container:xcoding_container, cur_state:S_DSMPXC_XCODE,
event:E_DSMP_CC_DELETE_STREAM, next_state:CNFSM_NO_STATE_CHANGE
00:10:50:no_stream_in_session
00:10:50:dsmpxc_act_stop_rsc::state = S_DSMPXC_XCODE event = CNFSM_LAMBDA_EVENT 
00:10:50:dsmp_set_state_var:message to DSP
    successful,ret::4
00:10:50:CNFSM:cur_container:xcoding_container, cur_state:S_DSMPXC_XCODE,
event:CNFSM_LAMBDA_EVENT, next_state:S_DSMPXC_CLOSING
00:10:50:dsmp_is_ret_succ::
00:10:50:dsmpxc_act_dealloc_rsc::state = S_DSMPXC_CLOSING event = CNFSM_LAMBDA_EVENT 
00:10:50:dsmp_set_state_var:message to DSP
    successful,ret::4
00:10:50:CNFSM:cur_container:xcoding_container, cur_state:S_DSMPXC_CLOSING,
event:CNFSM_LAMBDA_EVENT, next_state:S_DSMPXC_STILL_CLOSING
00:10:50:CNFSM:new_container:xcoder_container
00:10:50:dsmp_is_ret_succ::
00:10:50:dsmpxc_act_start_timer::state = S_DSMPXC_STILL_CLOSING event = CNFSM_LAMBDA_EVENT 
00:10:50:CNFSM:cur_container:xcoder_container, cur_state:S_DSMPXC_STILL_CLOSING,
event:CNFSM_LAMBDA_EVENT, next_state:CNFSM_NO_STATE_CHANGE
00:10:50:dsmp_process_event:evt->requestType = E_DSMP_DSPRM_CLOSE_COMPLETE
00:10:50:dsmpxc_act_terminate::state = S_DSMPXC_STILL_CLOSING event =
E_DSMP_DSPRM_CLOSE_COMPLETE 
00:10:50:dsmpxc_act_terminate Removing the program based stream = 1
00:10:50:CNFSM:cur_container:xcoder_container, cur_state:S_DSMPXC_STILL_CLOSING,
event:E_DSMP_DSPRM_CLOSE_COMPLETE, next_state:CNFSM_NULL_STATE
00:10:50:dsmp_free_session
00:10:50:dsmp_process_event:

The following is sample output from the debug voip dsmp command, with Cisco IOS Release 12.3(14)T software, when a VoIP call is in transition to the connected state:

Router# debug voip dsmp
 
*May 22 04:12:17.775: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmpAddStream: callID = 24, confID = -1, streamType = TDM, streamDir = INPUT, ownerContext = 0x0000000C, codec = 0x0, fax_modem_type =0, XmitFn = 0x00000000, multicastStreamDtmfType = 0
*May 22 04:12:17.775: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmpAddStream: streamID = 2
*May 22 04:12:17.779: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmpAddStream: callID = 24, confID = -1, streamType = TDM, streamDir = OUTPUT, ownerContext = 0x0000000C, codec = 0x0, fax_modem_type =0, XmitFn = 0x00000000, multicastStreamDtmfType = 0
*May 22 04:12:17.779: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmpAddStream: streamID = 3
*May 22 04:12:17.779: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmpReserveGwResource: sIdLegInput1 = 2, sIdLegOutput1 = 3, requesterCallID = 24, respFunc = 0x61CD1EE0
*May 22 04:12:17.787: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmp_new_or_existing_gw_session: created a new session = 0x657EEE20
*May 22 04:12:17.787: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmp_enlist_stream: Stream 2 is enlisted, total = 1
*May 22 04:12:17.787: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmp_enlist_stream: Stream 3 is enlisted, total = 2
*May 22 04:12:17.787: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmp_exec:  
   [state:S_DSMP_INITIAL, event:E_DSMP_CC_RESERVE_RESOURCE_REQ]
*May 22 04:12:17.791: CNFSM: cur_container:rsc_main_container, cur_state:S_DSMP_INITIAL, event:E_DSMP_CC_RESERVE_RESOURCE_REQ
*May 22 04:12:17.791: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmp_gw_act_alloc_rsc: 
*May 22 04:12:17.791: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmp_decide_pgm_based_stm: 
*May 22 04:12:17.791: //-1/F401BFC88006/DSMP:():-1/dsmp_set_state_var: Message to DSP is successful
*May 22 04:12:17.791: CNFSM: new_container:rsc_allocating_container
*May 22 04:12:17.791: CNFSM: next_state:S_DSMP_RSC_ALLOCATING
*May 22 04:12:17.791: //-1/F401BFC88006/DSMP:():-1/dsmp_gw_act_rsc_alloc_succ: 
*May 22 04:12:17.791: CNFSM: next_state:S_DSMP_RSC_ALLOCATED
*May 22 04:12:18.047: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmpReserveGwResource: sIdLegInput1 = 2, sIdLegOutput1 = 3, requesterCallID = 24, respFunc = 0x61CD1EE0
*May 22 04:12:18.047: //-1/F401BFC88006/DSMP:():-1/dsmp_exec:  
   [state:S_DSMP_RSC_ALLOCATED, event:E_DSMP_CC_RESERVE_RESOURCE_REQ]
*May 22 04:12:18.051: CNFSM: cur_container:rsc_allocating_container, cur_state:S_DSMP_RSC_ALLOCATED, event:E_DSMP_CC_RESERVE_RESOURCE_REQ
*May 22 04:12:18.051: CNFSM: new_container:rsc_main_container
*May 22 04:12:18.051: //-1/F401BFC88006/DSMP:():-1/dsmp_gw_act_rsc_reopen: 
*May 22 04:12:18.051: //-1/F401BFC88006/DSMP:():-1/dsmp_set_state_var: Message to DSP is successful
*May 22 04:12:18.051: CNFSM: history stored state: S_DSMP_RSC_ALLOCATED, container: rsc_allocating_container
*May 22 04:12:18.051: CNFSM: updated current container: rsc_main_container
*May 22 04:12:18.051: CNFSM: next_state:S_DSMP_RSC_REOPENING
*May 22 04:12:18.051: //-1/F401BFC88006/DSMP:():-1/dsmp_gw_act_rsc_alloc_succ: 
*May 22 04:12:18.051: CNFSM: restoring history state: S_DSMP_RSC_ALLOCATED
*May 22 04:12:18.055: CNFSM: restoring history container: rsc_allocating_container
*May 22 04:12:18.055: CNFSM: new_container:rsc_allocating_container
*May 22 04:12:18.055: CNFSM: next_state:S_DSMP_RSC_ALLOCATED
*May 22 04:12:18.055: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmpStopPlay: sIdLegOutput = 3
*May 22 04:12:18.059: //-1/F401BFC88006/DSMP:():-1/dsmp_exec:  
   [state:S_DSMP_RSC_ALLOCATED, event:E_DSMP_CC_STOP_PLAY_REQ]
*May 22 04:12:18.059: CNFSM: cur_container:rsc_allocating_container, cur_state:S_DSMP_RSC_ALLOCATED, event:E_DSMP_CC_STOP_PLAY_REQ
*May 22 04:12:18.059: CNFSM: new_container:rsc_main_container
*May 22 04:12:18.059: //-1/F401BFC88006/DSMP:():-1/dsmp_gw_act_ignore: 
*May 22 04:12:18.059: CNFSM: next_state:CNFSM_NO_STATE_CHANGE
*May 22 04:12:18.063: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmpAddStream: callID = 23, confID = 12, streamType = PACKET, streamDir = INPUT, ownerContext = 0x0000000C, codec = 0x1, fax_modem_type =0, XmitFn = 0x6158E1F8, multicastStreamDtmfType = -1
*May 22 04:12:18.067: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmpAddStream: streamID = 1
*May 22 04:12:18.067: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmpAddStream: callID = 23, confID = 12, streamType = PACKET, streamDir = OUTPUT, ownerContext = 0x0000000C, codec = 0x1, fax_modem_type =0, XmitFn = 0x6158E1F8, multicastStreamDtmfType = -1
*May 22 04:12:18.067: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmpAddStream: streamID = 4
*May 22 04:12:18.071: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmpUpdateRtpMode: sId = 1, callID = 24, mode = 1
*May 22 04:12:18.071: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmpModifyReq: sIdLegInput = 1, sIdLegOutput = 4, callID = 24
*May 22 04:12:18.075: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmpConnectGwBinderReq:  
   sIdLegInputTdm1=2, sIdLegOutputPak1=4, sIdLegInputPak2=1, sIdLegOutputTdm2=3, Call Id=24
*May 22 04:12:18.075: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmpModifyReq: sIdLegInput = 2, sIdLegOutput = 3, callID = 24FORKING Parameters are forking mask: 7, simple_forking_codec_mask: 327679, complex_forking_codec_mask 327679
*May 22 04:12:18.075: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmp_process_event: No session is associated to the streams.
*May 22 04:12:18.075: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmp_save_modify_caps: 
*May 22 04:12:18.079: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmp_save_modify_packet_stream_caps: 
*May 22 04:12:18.079: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmp_leg_voice_elog_write: 
*May 22 04:12:18.079: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmp_leg_voice_elog_write:  
   CALL_ERROR; DSMP Session Is NULL
*May 22 04:12:18.079: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmp_leg_voice_elog_write:exit@2908
*May 22 04:12:18.079: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmp_leg_voice_elog_write: 
*May 22 04:12:18.079: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmp_leg_voice_elog_write:  
   CALL_ERROR; DSMP Session Is NULL
*May 22 04:12:18.079: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmp_leg_voice_elog_write:exit@2908
*May 22 04:12:18.079: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmp_leg_voice_elog_write: 
*May 22 04:12:18.079: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmp_leg_voice_elog_write:  
   CALL_ERROR; DSMP Session Is NULL
*May 22 04:12:18.079: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmp_leg_voice_elog_write:exit@2908
*May 22 04:12:18.083: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmp_leg_voice_elog_write: 
*May 22 04:12:18.083: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmp_leg_voice_elog_write:  
   CALL_ERROR; DSMP Session Is NULL
*May 22 04:12:18.083: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmp_leg_voice_elog_write:exit@2908
*May 22 04:12:18.083: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmp_save_modify_packet_stream_caps: 
*May 22 04:12:18.083: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmp_save_modify_tdm_stream_caps: 
*May 22 04:12:18.083: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmp_save_modify_tdm_stream_caps:exit@385
*May 22 04:12:18.087: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmp_save_modify_tdm_stream_caps: 
*May 22 04:12:18.087: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmp_save_modify_tdm_stream_caps:exit@385
*May 22 04:12:18.087: //-1/F401BFC88006/DSMP:():-1/dsmp_enlist_stream: Stream 1 is enlisted, total = 3
*May 22 04:12:18.087: //-1/F401BFC88006/DSMP:():-1/dsmp_enlist_stream: Stream 4 is enlisted, total = 4
*May 22 04:12:18.087: //-1/F401BFC88006/DSMP:():-1/dsmp_exec:  
   [state:S_DSMP_RSC_ALLOCATED, event:E_DSMP_CC_CONNECT_REQ]
*May 22 04:12:18.091: CNFSM: cur_container:rsc_allocating_container, cur_state:S_DSMP_RSC_ALLOCATED, event:E_DSMP_CC_CONNECT_REQ
*May 22 04:12:18.091: //-1/F401BFC88006/DSMP:():-1/dsmp_is_req_not_in_proc_dsp_ready: 
*May 22 04:12:18.091: //-1/F401BFC88006/DSMP:():-1/dsmp_gw_act_rsc_init: 
*May 22 04:12:18.091: //-1/F401BFC88006/DSMP:():-1/dsmp_set_state_var: Message to DSP is successful
*May 22 04:12:18.091: CNFSM: history stored state: S_DSMP_RSC_ALLOCATED, container: rsc_allocating_container
*May 22 04:12:18.091: CNFSM: new_container:rsc_main_container
*May 22 04:12:18.095: CNFSM: next_state:S_DSMP_RSC_INITING
*May 22 04:12:18.095: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmp_decide_pgm_based_stm: 
*May 22 04:12:18.095: //-1/F401BFC88006/DSMP:():-1/dsmp_gw_act_rsc_init_succ: pgm_base_stm_id = 1, service_id = 26, codec =4
*May 22 04:12:18.095: //-1/F401BFC88006/DSMP:():-1/dsmp_set_state_var: Message to DSP is successful
*May 22 04:12:18.099: CNFSM: next_state:S_DSMP_RSC_OPENING
*May 22 04:12:18.099: //-1/F401BFC88006/DSMP:():-1/dsmp_gw_act_rsc_open_succ: 
*May 22 04:12:18.099: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmp_leg_voice_elog_write: 
*May 22 04:12:18.099: //-1/F401BFC88006/DSMP:():-1/dsmp_conf_static_params: 
*May 22 04:12:18.099: //-1/F401BFC88006/DSMP:():-1/dsmp_conf_static_params: servic_type=1 base stream=1 tdm_caps=0x6557E454 pkt_caps=0x6557EC3C
*May 22 04:12:18.099: //-1/F401BFC88006/DSMP:():-1/dsmp_conf_static_params: 
*May 22 04:12:18.103:  ip_tones = 0, pstn_tones = 0
*May 22 04:12:18.103: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmp_conf_static_params: voice detection disabled
*May 22 04:12:18.103: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmp_conf_static_params: silence detection disabled
*May 22 04:12:18.103: //-1/F401BFC88006/DSMP:():-1/dsmp_set_state_var: Message to DSP is successful
*May 22 04:12:18.107: CNFSM: next_state:S_DSMP_RSC_STATIC_CONF
*May 22 04:12:18.107: //-1/F401BFC88006/DSMP:():-1/dsmp_gw_act_start_service: 
*May 22 04:12:18.107: //-1/F401BFC88006/DSMP:():-1/dsmp_set_state_var: Message to DSP is successful
*May 22 04:12:18.107: CNFSM: next_state:S_DSMP_RSC_STARTING
*May 22 04:12:18.107: //-1/F401BFC88006/DSMP:():-1/dsmp_act_rsc_start_succ: 
*May 22 04:12:18.107: //-1/F401BFC88006/DSMP:():-1/dsmp_conf_dynamic_params: 
*May 22 04:12:18.111: //-1/F401BFC88006/DSMP:():-1/dsmp_conf_dynamic_params: servic_type=1 base stream=1
*May 22 04:12:18.111: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmp_leg_voice_elog_write: 
*May 22 04:12:18.111: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmp_leg_voice_elog_write: 
*May 22 04:12:18.111: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmp_leg_voice_elog_write: 
*May 22 04:12:18.111: //-1/F401BFC88006/DSMP:():-1/dsmp_conf_detector_params: 
*May 22 04:12:18.115: //-1/F401BFC88006/DSMP:():-1/dsmp_set_state_var: Message to DSP is successful
*May 22 04:12:18.115: CNFSM: next_state:S_DSMP_RSC_DYNAMIC_CONF
*May 22 04:12:18.115: CNFSM: new_container:rsc_running_container
*May 22 04:12:18.115: CNFSM: next_state:S_DSMP_MCAST_CHECK
*May 22 04:12:18.115: //-1/F401BFC88006/DSMP:():-1/dsmp_is_mcast: 
*May 22 04:12:18.119: //-1/F401BFC88006/DSMP:():-1/dsmp_is_mcast:exit@1487
*May 22 04:12:18.119: //-1/F401BFC88006/DSMP:():-1/dsmp_is_not_mcast: 
*May 22 04:12:18.119: //-1/F401BFC88006/DSMP:():-1/dsmp_is_mcast: 
*May 22 04:12:18.119: //-1/F401BFC88006/DSMP:():-1/dsmp_is_mcast:exit@1487
*May 22 04:12:18.119: //-1/F401BFC88006/DSMP:():-1/dsmp_is_not_mcast:exit@1500
*May 22 04:12:18.119: CNFSM: next_state:S_DSMP_DTMF_FSK_MODE_CHECK
*May 22 04:12:18.119: //-1/F401BFC88006/DSMP:():-1/dsmp_is_fsk_or_dtmf: 
*May 22 04:12:18.123: //-1/F401BFC88006/DSMP:():-1/dsmp_is_diagnostic: 
*May 22 04:12:18.123: //-1/F401BFC88006/DSMP:():-1/dsmp_is_diagnostic:exit@1587
*May 22 04:12:18.123: //-1/F401BFC88006/DSMP:():-1/dsmp_is_not_dtmf_fsk: 
*May 22 04:12:18.123: //-1/F401BFC88006/DSMP:():-1/dsmp_is_fsk_or_dtmf: 
*May 22 04:12:18.123: //-1/F401BFC88006/DSMP:():-1/dsmp_is_diagnostic: 
*May 22 04:12:18.123: //-1/F401BFC88006/DSMP:():-1/dsmp_is_diagnostic:exit@1587
*May 22 04:12:18.123: //-1/F401BFC88006/DSMP:():-1/dsmp_is_not_dtmf_fsk:exit@1600
*May 22 04:12:18.127: CNFSM: next_state:S_DSMP_NOT_DTMF_FSK
*May 22 04:12:18.127: //-1/F401BFC88006/DSMP:():-1/dsmp_is_simple_voice: 
*May 22 04:12:18.127: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmp_get_stm_service_type: 
*May 22 04:12:18.127: //-1/F401BFC88006/DSMP:():-1/dsmp_gw_act_simple_voice_start: 
*May 22 04:12:18.127: //-1/F401BFC88006/DSMP:():-1/dsmp_connect_req_done: 
*May 22 04:12:18.127: //-1/F401BFC88006/DSMP:():-1/dsmp_enlist_connection: Connection is added, enlisted LegIn: 2, enlisted LegOut: 4
*May 22 04:12:18.131: //-1/F401BFC88006/DSMP:():-1/dsmp_enlist_connection: Connection is added, enlisted LegIn: 1, enlisted LegOut: 3
*May 22 04:12:18.131: CNFSM: new_container:simple_voice_container
*May 22 04:12:18.131: CNFSM: next_state:S_DSMP_VC_RUNNING
*May 22 04:12:18.131: //-1/F401BFC88006/DSMP:():-1/dsmp_exec:  
   [state:S_DSMP_VC_RUNNING, event:E_DSMP_CC_MODIFY_REQ]
*May 22 04:12:18.135: CNFSM: cur_container:simple_voice_container, cur_state:S_DSMP_VC_RUNNING, event:E_DSMP_CC_MODIFY_REQ
*May 22 04:12:18.135: CNFSM: new_container:rsc_running_container
*May 22 04:12:18.135: //-1/F401BFC88006/DSMP:():-1/dsmp_gw_act_save_modify_caps: 
*May 22 04:12:18.135: //-1/F401BFC88006/DSMP:():-1/dsmp_save_modify_caps: 
*May 22 04:12:18.135: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmp_save_modify_packet_stream_caps: 
*May 22 04:12:18.139: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmp_save_modify_packet_stream_caps: 
*May 22 04:12:18.139: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmp_save_modify_tdm_stream_caps: 
*May 22 04:12:18.139: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmp_save_modify_tdm_stream_caps: 
*May 22 04:12:18.139: //-1/F401BFC88006/DSMP:():-1/dsmp_save_stream_detectors: 
*May 22 04:12:18.139: CNFSM: history stored state: S_DSMP_VC_RUNNING, container: simple_voice_container
*May 22 04:12:18.139: CNFSM: updated current container: rsc_running_container
*May 22 04:12:18.143: CNFSM: next_state:S_DSMP_MODIFY_CAPS_SAVED
*May 22 04:12:18.143: //-1/F401BFC88006/DSMP:():-1/dsmp_is_modify_to_modem_passthru: 
*May 22 04:12:18.143: //-1/F401BFC88006/DSMP:():-1/dsmp_is_static_params_changed: 
*May 22 04:12:18.143: //-1/F401BFC88006/DSMP:():-1/dsmp_is_modify_to_modem_passthru: 
*May 22 04:12:18.143: //-1/F401BFC88006/DSMP:():-1/dsmp_is_dynamic_params_changed: 
*May 22 04:12:18.143: //-1/F401BFC88006/DSMP:():-1/dsmp_is_modify_to_modem_passthru: 
*May 22 04:12:18.143: //-1/F401BFC88006/DSMP:():-1/dsmp_gw_act_dynamic_params_changed: 
*May 22 04:12:18.147: //-1/F401BFC88006/DSMP:():-1/dsmp_conf_dynamic_params: 
*May 22 04:12:18.147: //-1/F401BFC88006/DSMP:():-1/dsmp_conf_dynamic_params: servic_type=1 base stream=1
*May 22 04:12:18.147: //-1/F401BFC88006/DSMP:():-1/dsmp_conf_detector_params: 
*May 22 04:12:18.147: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmp_conf_detector_params: fax: 1
*May 22 04:12:18.147: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmp_conf_detector_params: modem: 1
*May 22 04:12:18.151: CNFSM: restoring history state: S_DSMP_VC_RUNNING
*May 22 04:12:18.151: CNFSM: restoring history container: simple_voice_container
*May 22 04:12:18.151: CNFSM: new_container:simple_voice_container
*May 22 04:12:18.151: CNFSM: next_state:S_DSMP_VC_RUNNING
*May 22 04:12:18.163: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmpUpdateRtpMode: sId = 1, callID = 24, mode = 3
*May 22 04:12:18.163: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmpUpdateRtpMode: sId = 1, callID = 24, mode = 3
*May 22 04:12:30.947: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmpUpdateRtpMode: sId = 1, callID = 24, mode = 3

The following is sample output from the debug voip dsmp command, with Cisco IOS Release 12.3(14)T software, when a VoIP call is in transition from connected to the disconnected state:

Router# debug voip dsmp
 
 
*May 22 04:12:30.951: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmpDisconnectGwBinder: sIdLegInputTdm1 = 2, sIdLegOutputPak1 = 4, sIdLegInputPak2 = 1, sIdLegOutputTdm2 = 3 requesterCallID = 24
*May 22 04:12:30.951: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmpDeleteStream: streamID = 1, callID = 23, ownerContext = 0x00000000
*May 22 04:12:30.951: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmpDeleteStream: streamID = 4, callID = 23, ownerContext = 0x00000000
*May 22 04:12:30.951: //-1/F401BFC88006/DSMP:():-1/dsmp_exec:  
   [state:S_DSMP_VC_RUNNING, event:E_DSMP_CC_DISCONNECT]
*May 22 04:12:30.955: CNFSM: cur_container:simple_voice_container, cur_state:S_DSMP_VC_RUNNING, event:E_DSMP_CC_DISCONNECT
*May 22 04:12:30.955: CNFSM: new_container:rsc_running_container
*May 22 04:12:30.955: //-1/F401BFC88006/DSMP:():-1/dsmp_gw_act_cc_disconnect: 
*May 22 04:12:30.955: //-1/F401BFC88006/DSMP:():-1/dsmp_delist_connection: Connection is delisted, delisted LegIn: 2, delisted LegOut: 4, total conn_count is = 1
*May 22 04:12:30.955: //-1/F401BFC88006/DSMP:():-1/dsmp_delist_connection: Connection is delisted, delisted LegIn: 1, delisted LegOut: 3, total conn_count is = 0
*May 22 04:12:30.955: CNFSM: next_state:CNFSM_NO_STATE_CHANGE
*May 22 04:12:30.955: //-1/F401BFC88006/DSMP:():-1/dsmp_exec:  
   [state:S_DSMP_VC_RUNNING, event:E_DSMP_DELETE_STREAM]
*May 22 04:12:30.959: CNFSM: cur_container:simple_voice_container, cur_state:S_DSMP_VC_RUNNING, event:E_DSMP_DELETE_STREAM
*May 22 04:12:30.959: CNFSM: new_container:rsc_running_container
*May 22 04:12:30.959: CNFSM: new_container:rsc_main_container
*May 22 04:12:30.959: //-1/F401BFC88006/DSMP:():-1/dsmp_not_last_stream: 
*May 22 04:12:30.959: //-1/F401BFC88006/DSMP:():-1/dsmp_is_last_stream: 
*May 22 04:12:30.959: //-1/F401BFC88006/DSMP:():-1/dsmp_gw_act_not_last_stream: 
*May 22 04:12:30.959: //-1/F401BFC88006/DSMP:():-1/remove_stream_from_DB: 
*May 22 04:12:30.959: //-1/F401BFC88006/DSMP:():-1/process_software_multicast_streams: 
*May 22 04:12:30.959: CNFSM: next_state:CNFSM_NO_STATE_CHANGE
*May 22 04:12:30.959: //-1/F401BFC88006/DSMP:():-1/dsmp_exec:  
   [state:S_DSMP_VC_RUNNING, event:E_DSMP_DELETE_STREAM]
*May 22 04:12:30.959: CNFSM: cur_container:simple_voice_container, cur_state:S_DSMP_VC_RUNNING, event:E_DSMP_DELETE_STREAM
*May 22 04:12:30.963: CNFSM: new_container:rsc_running_container
*May 22 04:12:30.963: CNFSM: new_container:rsc_main_container
*May 22 04:12:30.963: //-1/F401BFC88006/DSMP:():-1/dsmp_not_last_stream: 
*May 22 04:12:30.963: //-1/F401BFC88006/DSMP:():-1/dsmp_is_last_stream: 
*May 22 04:12:30.963: //-1/F401BFC88006/DSMP:():-1/dsmp_gw_act_not_last_stream: 
*May 22 04:12:30.963: //-1/F401BFC88006/DSMP:():-1/remove_stream_from_DB: 
*May 22 04:12:30.963: //-1/F401BFC88006/DSMP:():-1/process_software_multicast_streams: 
*May 22 04:12:30.963: CNFSM: next_state:CNFSM_NO_STATE_CHANGE
*May 22 04:12:30.967: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmpStopPlay: sIdLegOutput = 3
*May 22 04:12:30.975: //-1/F401BFC88006/DSMP:():-1/dsmp_exec:  
   [state:S_DSMP_VC_RUNNING, event:E_DSMP_CC_STOP_PLAY_REQ]
*May 22 04:12:30.975: CNFSM: cur_container:simple_voice_container, cur_state:S_DSMP_VC_RUNNING, event:E_DSMP_CC_STOP_PLAY_REQ
*May 22 04:12:30.975: CNFSM: new_container:rsc_running_container
*May 22 04:12:30.975: CNFSM: new_container:rsc_main_container
*May 22 04:12:30.975: //-1/F401BFC88006/DSMP:():-1/dsmp_gw_act_ignore: 
*May 22 04:12:30.975: CNFSM: next_state:CNFSM_NO_STATE_CHANGE
*May 22 04:12:31.011: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmpStopPlay: sIdLegOutput = 3
*May 22 04:12:31.011: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmpDeleteStream: streamID = 2, callID = 24, ownerContext = 0x0000000C
*May 22 04:12:31.011: //-1/xxxxxxxxxxxx/DSMP:():-1/dsmpDeleteStream: streamID = 3, callID = 24, ownerContext = 0x0000000C
*May 22 04:12:31.015: //-1/F401BFC88006/DSMP:():-1/dsmp_exec:  
   [state:S_DSMP_VC_RUNNING, event:E_DSMP_CC_STOP_PLAY_REQ]
*May 22 04:12:31.015: CNFSM: cur_container:simple_voice_container, cur_state:S_DSMP_VC_RUNNING, event:E_DSMP_CC_STOP_PLAY_REQ
*May 22 04:12:31.015: CNFSM: new_container:rsc_running_container
*May 22 04:12:31.015: CNFSM: new_container:rsc_main_container
*May 22 04:12:31.015: //-1/F401BFC88006/DSMP:():-1/dsmp_gw_act_ignore: 
*May 22 04:12:31.015: CNFSM: next_state:CNFSM_NO_STATE_CHANGE
*May 22 04:12:31.015: //-1/F401BFC88006/DSMP:():-1/dsmp_exec:  
   [state:S_DSMP_VC_RUNNING, event:E_DSMP_DELETE_STREAM]
*May 22 04:12:31.015: CNFSM: cur_container:simple_voice_container, cur_state:S_DSMP_VC_RUNNING, event:E_DSMP_DELETE_STREAM
*May 22 04:12:31.019: CNFSM: new_container:rsc_running_container
*May 22 04:12:31.019: CNFSM: new_container:rsc_main_container
*May 22 04:12:31.019: //-1/F401BFC88006/DSMP:():-1/dsmp_not_last_stream: 
*May 22 04:12:31.019: //-1/F401BFC88006/DSMP:():-1/dsmp_is_last_stream: 
*May 22 04:12:31.019: //-1/F401BFC88006/DSMP:():-1/dsmp_gw_act_not_last_stream: 
*May 22 04:12:31.019: //-1/F401BFC88006/DSMP:():-1/remove_stream_from_DB: 
*May 22 04:12:31.019: //-1/F401BFC88006/DSMP:():-1/process_software_multicast_streams: 
*May 22 04:12:31.019: CNFSM: next_state:CNFSM_NO_STATE_CHANGE
*May 22 04:12:31.019: //-1/F401BFC88006/DSMP:():-1/dsmp_exec:  
   [state:S_DSMP_VC_RUNNING, event:E_DSMP_DELETE_STREAM]
*May 22 04:12:31.019: CNFSM: cur_container:simple_voice_container, cur_state:S_DSMP_VC_RUNNING, event:E_DSMP_DELETE_STREAM
*May 22 04:12:31.019: CNFSM: new_container:rsc_running_container
*May 22 04:12:31.023: CNFSM: new_container:rsc_main_container
*May 22 04:12:31.023: //-1/F401BFC88006/DSMP:():-1/dsmp_not_last_stream: 
*May 22 04:12:31.023: //-1/F401BFC88006/DSMP:():-1/dsmp_is_last_stream: 
*May 22 04:12:31.023: //-1/F401BFC88006/DSMP:():-1/dsmp_is_last_stream: 
*May 22 04:12:31.023: //-1/F401BFC88006/DSMP:():-1/dsmp_gw_act_rsc_stop: 
*May 22 04:12:31.023: //-1/F401BFC88006/DSMP:():-1/remove_stream_from_DB: 
*May 22 04:12:31.023: //-1/F401BFC88006/DSMP:():-1/process_software_multicast_streams: 
*May 22 04:12:31.023: //-1/F401BFC88006/DSMP:():-1/dsmp_set_state_var: Message to DSP is successful
*May 22 04:12:31.023: CNFSM: history stored state: S_DSMP_VC_RUNNING, container: simple_voice_container
*May 22 04:12:31.023: CNFSM: updated current container: rsc_main_container
*May 22 04:12:31.027: CNFSM: new_container:rsc_closing_container
*May 22 04:12:31.027: CNFSM: next_state:S_DSMP_RSC_STOPPING
*May 22 04:12:31.027: //-1/F401BFC88006/DSMP:():-1/dsmp_gw_act_rsc_stopping_close: 
*May 22 04:12:31.027: //-1/F401BFC88006/DSMP:():-1/dsmp_set_state_var: Message to DSP is successful
*May 22 04:12:31.027: CNFSM: next_state:S_DSMP_DSPMGR_CLOSING
*May 22 04:12:31.027: //-1/F401BFC88006/DSMP:():-1/dsmp_exec:  
   [state:S_DSMP_DSPMGR_CLOSING, event:E_DSMP_DSPRM_CLOSE_COMPLETE]
*May 22 04:12:31.027: CNFSM: cur_container:rsc_closing_container, cur_state:S_DSMP_DSPMGR_CLOSING, event:E_DSMP_DSPRM_CLOSE_COMPLETE
*May 22 04:12:31.027: //-1/F401BFC88006/DSMP:():-1/dsmp_gw_act_dspmgr_closing_complete: 
*May 22 04:12:31.031: //-1/F401BFC88006/DSMP:():-1/remove_stream_from_DB: 
*May 22 04:12:31.031: //-1/F401BFC88006/DSMP:():-1/process_software_multicast_streams: 
*May 22 04:12:31.031: //-1/F401BFC88006/DSMP:():-1/remove_stream_from_DB: 
*May 22 04:12:31.031: //-1/F401BFC88006/DSMP:():-1/process_software_multicast_streams: 
*May 22 04:12:31.031: CNFSM: next_state:CNFSM_NULL_STATE
*May 22 04:12:31.031: //-1/F401BFC88006/DSMP:():-1/dsmp_free_session: 

Examples

The following examples show output for variations of the debug voip dspapi command:

• debug voip dspapi
• debug voip dspapi
• debug voip dspapi

For these examples, the topology shown in the figure below is used.

Figure 4. Network Topology for debug voip dspapi Examples

Examples

Router# debug voip dspapi command
voip dspapi command debugging is ON
Router#
*Apr 18 21:33:48.347: //-1/CD89F6A78020/DSPAPI/[2/1:23]/dsp_init:
*Apr 18 21:33:48.347: //-1/CD89F6A78020/DSPAPI/[2/1:23]/dsp_voice_config_params:
*Apr 18 21:33:48.347:     9 parameters

The following lines show encapsulation settings, jitter, inband signaling, echo cancellation, gain, and other quality of service (QoS) settings:

 
   [0] ENCAP RTP: Tx SSRC=0, Rx SSRC=0, Tx VPXCC=0, Rx VPXCC=0
    IFP payload type=122, SID support=1, TSE payload=101, Sequence number start=0
    Redundancy=0, ClearChannel payload type=0, Fax payload type=0
    Alaw PCM switchover=0, MuLAW PCM switchover=0
    DTMF payload type=0, NTE receive payload type=101
    Dynamic payload=0, Codec=g711ulaw
    [1] PO_JITTER: mode=2 initial=60(ms) max=200(ms) min=40(ms) fax_nom=300(ms)
    [2] INBAND_SIG: mode=0x1 enable
    [3] ECHO_CANCEL: Flags=0x37, Echo length=64(ms)
    [4] IDLE_CODE_DET: Enable=0, Code=0x0, Duration=6000(ms)
    [5] GAIN: Input=0.0(dB), Output=0.0(dB)
    [6] CNG: 1
    [7] INFO_FIELD_SIZE: 160 bytes
    [8] DIGIT_RELAY: 2
*Apr 18 21:33:48.359: //66/CD89F6A78020/DSPAPI/[2/1:23:66]/dsp_voice_get_capabilities:
*Apr 18 21:33:48.359: //66/CD89F6A78020/DSPAPI/[2/1:23:66]/dsp_stop_service:
    NONE (0)
*Apr 18 21:33:48.359: //66/CD89F6A78020/DSPAPI/[2/1:23:66]/dsp_open_service:
    G729IETF (25)
*Apr 18 21:33:48.359: //66/CD89F6A78020/DSPAPI/[2/1:23:66]/dsp_voice_config_params:

The following lines show settings for encapsulation, packet suppression, and voice activity detection (VAD):

*Apr 18 21:33:48.359:     3 parameters
    [0] ENCAP RTP: Tx SSRC=64, Rx SSRC=0, Tx VPXCC=0, Rx VPXCC=0
    IFP payload type=122, SID support=19, TSE payload=101, Sequence number start=3238
    Redundancy=0, ClearChannel payload type=125, Fax payload type=122
    Alaw PCM switchover=8, MuLAW PCM switchover=0
 
 DTMF payload type=121, NTE receive payload type=101
    Dynamic payload=0, Codec=g729r8
    [1] PAK_SUPPRESS: 0
    [2] VAD: Enable=1, Threshold=-38(dBm)
.
.
.
*Apr 18 21:33:48.363: //66/CD89F6A78020/DSPAPI/[2/1:23:66]/dsp_start_service:
    G729IETF (25)
*Apr 18 21:33:48.363: //66/CD89F6A78020/DSPAPI/[2/1:23:66]/dsp_voice_config_params:
*Apr 18 21:33:48.363:     1 parameter
    [0] VAD: Enable=1, Threshold=-38(dBm)
*Apr 18 21:33:50.867: //66/CD89F6A78020/DSPAPI/[2/1:23:66]/dsp_query_info:
    Request ID=1, Reset Flag=FALSE Q:PO_Delay PO_Error TX RX
.
.
.
*Apr 18 21:34:15.031: //66/CD89F6A78020/DSPAPI/[2/1:23:66]/dsp_query_info:
    Request ID=5, Reset Flag=TRUE Q:Error
*Apr 18 21:34:15.031: //66/CD89F6A78020/DSPAPI/[2/1:23:66]/dsp_query_info:
    Request ID=5, Reset Flag=TRUE Q:Levels
*Apr 18 21:34:15.031: //66/CD89F6A78020/DSPAPI/[2/1:23:66]/dsp_inband_tone_off:
*Apr 18 21:34:15.031: //66/CD89F6A78020/DSPAPI/[2/1:23:66]/dsp_stop_service:
    G729IETF (25)
*Apr 18 21:34:15.031: //66/CD89F6A78020/DSPAPI/[2/1:23:66]/dsp_close_service:
    G729IETF (25)

Examples

Router# debug voip dspapi inout
 
voip dspapi inout debugging is ON
*May  1 19:59:15.579: //67/2BA0E0758024/DSPAPI/[4/0/0 (67)]/dsp_init:
*May  1 19:59:15.579: //67/2BA0E0758024/DSPAPI/[4/0/0 (67)]/dsp_voice_config_params:
*May  1 19:59:15.579:     9 parameters

The following lines show encapsulation settings, jitter, inband signalling, echo cancellation, gain, and other quality of service (QoS) settings:

    [0] ENCAP RTP: Tx SSRC=0, Rx SSRC=0, Tx VPXCC=0, Rx VPXCC=0
    IFP payload type=122, SID support=1, TSE payload=101, Sequence number start=0
    Redundancy=0, ClearChannel payload type=0, Fax payload type=0
    Alaw PCM switchover=0, MuLAW PCM switchover=0
    DTMF payload type=0, NTE receive payload type=101
    Dynamic payload=0, Codec=g711ulaw
    [1] PO_JITTER: mode=2 initial=60(ms) max=200(ms) min=40(ms) fax_nom=300(ms)
    [2] INBAND_SIG: mode=0x1 enable
    [3] ECHO_CANCEL: Flags=0x17, Echo length=8(ms)
    [4] IDLE_CODE_DET: Enable=0, Code=0x0, Duration=6000(ms)
    [5] GAIN: Input=0.0(dB), Output=-6550.6(dB)
    [6] CNG: 1
    [7] INFO_FIELD_SIZE: 160 bytes
    [8] DIGIT_RELAY: 2
.
.
*May  1 19:59:15.587: //67/2BA0E0758024/DSPAPI/[4/0/0 (67)]/dsp_voice_get_capabilities:
*May  1 19:59:15.587: //67/2BA0E0758024/DSPAPI/[4/0/0 (67)]/dsp_stop_service:
    NONE (0)
*May  1 19:59:15.587: //67/2BA0E0758024/DSPAPI/[4/0/0 (67)]/dsp_open_service:
    G729IETF (25)
*May  1 19:59:15.587: //67/2BA0E0758024/DSPAPI/[4/0/0 (67)]/dsp_voice_config_params:
*May  1 19:59:15.587:     3 parameters
    [0] ENCAP RTP: Tx SSRC=0, Rx SSRC=0, Tx VPXCC=0, Rx VPXCC=0
    IFP payload type=122, SID support=19, TSE payload=101, Sequence number start=2977
    Redundancy=0, ClearChannel payload type=125, Fax payload type=122
    Alaw PCM switchover=8, MuLAW PCM switchover=0
    DTMF payload type=121, NTE receive payload type=101
    Dynamic payload=0, Codec=g729r8
    [1] PAK_SUPPRESS: 0
    [2] VAD: Enable=1, Threshold=-38(dBm)
*May  1 19:59:15.587: //67/2BA0E0758024/DSPAPI/[4/0/0 (67)]/dsp_idle_service:
    G729IETF (25)
*May  1 19:59:15.587: //67/2BA0E0758024/DSPAPI/[4/0/0 (67)]/dsp_voice_config_params:
*May  1 19:59:15.587:     3 parameters
    [0] INFO_FIELD_SIZE: 20 bytes
    [1] ENCAP RTP: Tx SSRC=64, Rx SSRC=0, Tx VPXCC=0, Rx VPXCC=0
    IFP payload type=122, SID support=19, TSE payload=101, Sequence number start=2977
    Redundancy=0, ClearChannel payload type=125, Fax payload type=122
    Alaw PCM switchover=8, MuLAW PCM switchover=0
    DTMF payload type=121, NTE receive payload type=101
    Dynamic payload=0, Codec=g729r8
    [2] DIGIT_RELAY: 2
*May  1 19:59:15.587: //67/2BA0E0758024/DSPAPI/[4/0/0 (67)]/dsp_start_service:
    G729IETF (25)
*May  1 19:59:15.587: //67/2BA0E0758024/DSPAPI/[4/0/0 (67)]/dsp_voice_config_params:
*May  1 19:59:15.587:     1 parameter
    [0] VAD: Enable=1, Threshold=-38(dBm)
*May  1 19:59:15.591: //67/2BA0E0758024/DSPAPI/[4/0/0 (67)]/dsp_inband_tone_on:
    Tone ID=1, Direction=2, Num frequencies=2
    Frequency(hz): a=440 b=480, Amplitude(dB): a=-16.0 b=-16.0
    Cadence1(ms): ON=2000 OFF=4000
    Cadence2(ms): ON=0 OFF=0
    Cadence3(ms): ON=0 OFF=0
    Cadence4(ms): ON=0 OFF=0
    Frequency(hz): a2=25667 b2=51816 a3=0 b3=1 a4=24596 b4=52484
    ITO option group: 1
*May  1 19:59:17.195: //67/2BA0E0758024/DSPAPI/[4/0/0 (67)]/dsp_inband_tone_off:
01:19:04: %PS-3-MULTFAIL: There is more than one failure with the  Power System 1; please resolve problems immediately

The following statistics repeat for each DSP query. The transmit (tx) and receive (rx) statistics show number of packets, comfort noise settings, duration, and packet status.

*May  1 19:59:18.051: //67/2BA0E0758024/DSPAPI/[4/0/0 (67)]/dsp_query_info:
    Request ID=1, Reset Flag=FALSE Q:PO_Delay PO_Error TX RX
*May  1 19:59:18.051: //67/2BA0E0758024/DSPAPI/[4/0/0 (67)]/dsp_tx_stats:
    Request ID=1, Packets: Voice=113, Signaling=0, ComfortNoise=1
    TX duration=2460(ms): Voice=2260(ms), FAX=0(ms)
*May  1 19:59:18.051: //67/2BA0E0758024/DSPAPI/[4/0/0 (67)]/dsp_rx_stats:
    Request ID=1, Packets: Voice=33, Signalling=0, ComfortNoise=1
    RX duration=840(ms): Voice=640(ms), FAX=0(ms)
    Packets: Bad Sequence=0, Bad Protocol=0, Late=0, Early=1
*May  1 19:59:18.051: //67/2BA0E0758024/DSPAPI/[4/0/0 (67)]/dsp_playout_delay_stats:
    Request ID=1, Current=70(ms), MIN=70(ms), MAX=70(ms)
    Clock offset=80(ms), Inter arrival jitter=67082420(ms)
*May  1 19:59:18.051: //67/2BA0E0758024/DSPAPI/[4/0/0 (67)]/dsp_playout_error_stats:
    Request ID=1
    Concealment: Predictive=0(ms), Interpolative=0(ms), Silence=0(ms)
    Retro Memory update=0(ms), Buffer overflow=10(ms)
    Talkspurt endpoint detection errors=0
*May  1 19:59:19.827: //67/2BA0E0758024/DSPAPI/[4/0/0 (67)]/dsp_query_info:
    Request ID=1, Reset Flag=FALSE Q:PO_Delay PO_Error TX RX
.
.
.

Examples

This output shows the fax relay statistics.

Router# debug voip dspapi 
voip dspapi debugging is ON
.
.
.
May  7 21:32:16.472 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_playout_error_stats: 
    Request ID=1
    Concealment: Predictive=0(ms), Interpolative=0(ms), Silence=0(ms)
    Retro Memory update=0(na)(ms), Buffer overflow=0(ms)
    Talkspurt endpoint detection errors=0
May  7 21:32:18.996 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_query_info: 
    Request ID=1, Reset Flag=FALSE Q:PO_Delay PO_Error TX RX 
May  7 21:32:18.996 UTC: np_vsmgr_dispatch_voice_rsp(1/3): VOICE_LINK_INFO_RSP_NTF Received 
May  7 21:32:18.996 UTC: request_id = 0x01, request_type = 0x0F
May  7 21:32:18.996 UTC: VOICE_TRANSMIT_STATS(1/3): num_voice_packets 36 num_sig_packets 0 num_cn_packets 1 transmit_duration AD2 end_point_detection 0
May  7 21:32:18.996 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_tx_stats: 
    Request ID=1, Packets: Voice=54, Signaling=0, ComfortNoise=1
    TX duration=2770(ms): Voice=0(ms), FAX=0(na)(ms)
May  7 21:32:18.996 UTC: VOICE_RECEIVE_STATS(1/3): num_voice_packets 20 num_sig_packets 0 num_cn_packets 2 receive_duration AD2  voice_receive_duration 0 num_pos_packets 0 num_bph_packets 0 num_late_packets 0 num_early_packets 0
May  7 21:32:18.996 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_rx_stats: 
    Request ID=1, Packets: Voice=32, Signalling=0, ComfortNoise=2
    RX duration=2770(ms): Voice=0(ms), FAX=0(na)(ms)
    Packets: Bad Sequence=0, Bad Protocol=0, Late=0, Early=0
May  7 21:32:18.996 UTC: VOICE_PLAYOUT_DELAY_STATS(1/3): curr_playout_delay 5A min_playout_delay 5A max_playout_delay 5A clock offset 2F07E72
May  7 21:32:19.000 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_playout_delay_stats: 
    Request ID=1, Current=90(ms), MIN=90(ms), MAX=90(ms)
    Clock offset=49315442(ms), Inter arrival jitter=0(na)(ms)
May  7 21:32:19.000 UTC: VOICE_PLAYOUT_ERROR(1/3): pred_conceal 0x0 inter_conceal 0x0 silence_conceal 0x0 buffer_overflow 0x0 endpt_det_error 0x0
May  7 21:32:19.000 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_playout_error_stats: 
    Request ID=1
    Concealment: Predictive=0(ms), Interpolative=0(ms), Silence=0(ms)
    Retro Memory update=0(na)(ms), Buffer overflow=0(ms)
    Talkspurt endpoint detection errors=0
May  7 21:32:21.456 UTC: VOICE_DET_STATUS_CHANGE_NTF(1/3): detector mask: 1 timestamp 51709BF8
May  7 21:32:21.456 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_voice_det_status_change: 
    Status=1, Timestamp=1366334456, Tone ID=0, Trigger=TRUE
May  7 21:32:21.464 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_voice_config_params:
May  7 21:32:21.464 UTC:     1 parameter 
    [0] PAK_SUPPRESS: 1
May  7 21:32:21.464 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_stop_service: 
    G729IETF (26)
May  7 21:32:21.464 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_fax_config_params: 
    1 parameters
May  7 21:32:21.464 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_open_service: 
    FAX_RELAY (27)
May  7 21:32:21.464 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_is_call_pending: 
    Call is not PENDING
May  7 21:32:21.464 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_set_call_pending: 
    Set PENDING state
May  7 21:32:21.504 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_fax_query_link_info: 
    Request ID=0, Group ID=1
May  7 21:32:21.504 UTC: vsm(1/3): np_vsmgr_voice_state_change() - state IDLE
May  7 21:32:21.504 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_is_call_pending: 
    Call is PENDING
May  7 21:32:21.504 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_reset_call_pending: 
    Reset PENDING state
May  7 21:32:21.504 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_call_status: 
    Status=PENDING_SUCCESS
May  7 21:32:21.504 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_fax_config_params: 
    11 parameters
May  7 21:32:21.504 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_start_service: 
    FAX_RELAY (27)
May  7 21:32:21.504 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_set_call_pending: 
    Set PENDING state
May  7 21:32:22.556 UTC: vsm(1/3): np_vsmgr_voice_state_change() - state ACTIVE
May  7 21:32:22.556 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_is_call_pending: 
    Call is PENDING
May  7 21:32:22.556 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_reset_call_pending: 
    Reset PENDING state
May  7 21:32:22.556 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_call_status: 
    Status=PENDING_SUCCESS
May  7 21:32:22.564 UTC: FAX_RELAY_LINK_INFO_RSP_NTF: slot 1 port 3 timestamp 76082770 fr-entered (20ms)
May  7 21:32:22.564 UTC: chan_id [3/1:D (8)] np_vsmgr_fax_relay_link_info_response:
May  7 21:32:29.712 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_fax_relay_t30_decode: 
    T30 msg : 0x4
May  7 21:32:30.436 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_fax_relay_t30_decode: 
    T30 msg : 0x2
May  7 21:32:30.784 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_fax_relay_t30_decode: 
    T30 msg : 0x1
May  7 21:32:33.936 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_fax_relay_t30_decode: 
    T30 msg : 0x42
May  7 21:32:34.280 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_fax_relay_t30_decode: 
    T30 msg : 0x41
May  7 21:32:39.676 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_fax_relay_t30_decode: 
    T30 msg : 0x21
May  7 21:32:39.676 UTC: np_fax_relay_t30_decode : Rx Direction
May  7 21:32:39.736 UTC: FARELAY_INIT_HS_MOD : 0x8
May  7 21:33:10.385 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_fax_relay_t30_decode: 
    T30 msg : 0x7D
May  7 21:33:13.073 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_fax_relay_t30_decode: 
    T30 msg : 0x31
May  7 21:33:15.217 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_fax_relay_t30_decode: 
    T30 msg : 0x5F
May  7 21:33:16.073 UTC: FAX_RELAY_DET_STATUS_CHANGE: slot: 1 port: 3 detector mask 0x2
May  7 21:33:16.073 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_fax_det_status: 
    Status=2, Timestamp=716372818
May  7 21:33:16.073 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_query_info: 
    Request ID=5, Reset Flag=FALSE Q:FaxRelay 
May  7 21:33:16.097 UTC: FAX_RELAY_DATA_PUMP_STATS(1/3) - valid:0x3FFC1F55 state_code:0x1 level:0x18 phase_jitter:0x0 freq_offset:0x0 eqm:0x7FFE jit_depth:0x38B jit_buf_ov:0x0 tx_paks:0x5A rx_pkts:0x62C inv_pkts:0x0 oos_pkts:0x0 hs_mod:0x8 init_hs_mod:0x8 tx_pgs:0x0 rx_pgs:0x1 ecm:0x1 nsf_country:0x0 nsf_manuf_len:0x20 nsf_manuf:0031B8EE80C48511DD0D0000DDDD0000DDDD000000000000000022ED00B0A400 encap:0x1 pkt_loss_con:0x0
May  7 21:33:16.097 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_fax_relay_stats: 
    Request ID=5, MAX jitter depth=907, MAX net RX qdepth=0(na)
    Jitter buffer overflow=0, Net RX qoverflow=0(na)
    Packets: TX=90 TX drops=0(na)
    Packets: RX=1580 RX loss=0(na), RX invalid=0, RX OOSequence=0
    HS modulation=8, Pages: TX=0 RX=1
    MAX TX In qdepth=0(na), MAX RX Out qdepth=0(na)
    MAX HS buffer usage=0(na), TX In qoverflow=0(na), RX Out qoverflow=0(na)
    FAX: State=1, level=24, Phase jitter=0, Frequency offset=0, EQM=32766
    Initial HS modulation=8, Fax Direction=2, ECM Enabled=1
    NSF Countery Code=0, nsf_manuf_code[32]=0031
    Encapsulation Protocol=1, Pkt Loss Conceal=0
May  7 21:33:16.101 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_stop_service: 
    FAX_RELAY (27)
May  7 21:33:16.101 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_open_service: 
    G729IETF (26)
May  7 21:33:16.101 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_is_call_pending: 
    Call is not PENDING
May  7 21:33:16.101 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_set_call_pending: 
    Set PENDING state
May  7 21:33:16.985 UTC: FAX_RELAY_LINK_INFO_RSP_NTF: slot 1 port 3 timestamp 76518179 fr-end
May  7 21:33:17.001 UTC: vsm(1/3): np_vsmgr_voice_state_change() - state IDLE
May  7 21:33:17.001 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_is_call_pending: 
    Call is PENDING
May  7 21:33:17.001 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_reset_call_pending: 
    Reset PENDING state
May  7 21:33:17.001 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_call_status: 
    Status=PENDING_SUCCESS
May  7 21:33:17.001 UTC: //8/D6635DD58005/DSPAPI/[1/0:3]/dsp_voice_config_params:
May  7 21:33:17.001 UTC:     4 parameters 
.
.
.

Examples

The following example displays output from the debug voip dump-file-acctcommand:

Router# debug voip dump-file-acct
 
*May 10 06:31:10.187: voice_file_acct_write:
*May 10 06:31:10.187: file_acct_write_local: file accounting buffer overflow,dumping to file
*May 10 06:31:10.187: voice_file_acct_initiate_dump_to_file: ctx_id=2, url=flash:cdr
*May 10 06:31:10.187: voice_file_acct_lock, ctx_id=2, refcnt=2
*May 10 06:31:10.187: create_file_acct_buffer: buffer of 63k created from chunk 0x46B5F474
*May 10 06:31:10.187: file_acct_write_local: message (len=640) written to file_acct:
30080 bytes left
*May 10 06:31:10.191: handle_file_acct_dump_request
*May 10 06:31:10.191: handle_file_acct_dump_request: pick up dump request (ctx_id=2)
*May 10 06:31:10.191: open_file_acct_dump_file: url=flash:cdr_ragdenCME1_05_10_2007_06_30_28.191  < == shows url.
*May 10 06:31:10.215:  Secondary mode file acct is successful
*May 10 06:31:10.215: handle_file_acct_dump_request :to_write is 29748  <== shows how much is written to.
*May 10 06:31:10.219: : File accounting,write successful to file
*May 10 06:31:10.219: handle_file_acct_dump_request :to_write is 640
*May 10 06:31:10.219: : File accounting,write successful to file
*May 10 06:31:10.323: voice_file_acct_unlock, ctx_id=2  refcnt=1

Examples

The following example shows sample output from the debug voip eddricommand:

21:00:53: eddri_interesting_ac_pt: new AC_curr 22 FD_curr -5 SD_curr -5
21:00:53: eddri_interesting_ac_pt: percent trigger diff 4
21:00:53: eddri_interesting_ac_pt: Interesting Point 
21:00:53: eddri_send_prefix_event_to_clients : reason 0x40 num_prefix 1

With the send prefix event the available circuits value and the triggers for reporting are updated.

21:00:53: eddri_send_prefix_event_to_clients attr 0xFF ev_id 1 qid 0x64209230 reason 0x40
eddri_dequeue_event : dequeue event 
21:00:53: eddri_interesting_ac_pt : tc 23 IAC 22 lwm 5 hwm 50 pct_trigger 2 oneMinusW 933
21:00:53: eddri_interesting_ac_pt: old AC_curr 23 FD_curr 0 SD_curr 0
21:00:53: eddri_interesting_ac_pt: new AC_curr 22 FD_curr -5 SD_curr -5
21:00:53: eddri_interesting_ac_pt: percent trigger diff 4
21:00:53: eddri_interesting_ac_pt: Interesting Point 
21:00:53: eddri_send_prefix_event_to_clients : reason 0x40 num_prefix 1

Examples

The following shows sample output from the debug voip enum detail command:

The output shows the match number as 5108891234, enum table as 10. Rule 1 in table 10 matched the pattern and after applying the replacement rule, the resulting string is 5108891234. The enum query is sent out for the domain 4.3.2.1.9.8.8.0.1.5.e164.cisco.com. The output then shows the matching Naming Authority Pointer (NAPTR) records obtained in the response. The records are then processed and the final URLs (contact lists) are shown toward the end.

Router# debug voip enum detail
enum_resolve_domain:match_num 5108891234 table_indx 10
enum_resolve_domain:rule 1 result string 5108891234
generate_enum_search_string :search string 4.3.2.1.9.8.8.0.1.5.e164.cisco.com
enum_dns_query:name = 4.3.2.1.9.8.8.0.1.5.e164.cisco.com type = 35, ns_server = 0
order 100 pref 10 service sip+E2U flag U
regexp /^.*$/sip:5108891234@1.8.50.14/ replacement 
order 200 pref 10 service h323+E2U flag U
regexp /^.*$/h323:5555@1.5.1.1/ replacement 
num_elem = 2
NAPTR Record :order 100 pref 10 service sip+E2U
               flags U regexp /^.*$/sip:5108891234@1.8.50.14/
               replacement 
NAPTR Record :order 200 pref 10 service h323+E2U
               flags U regexp /^.*$/h323:5555@1.5.1.1/
               replacement 
decode_naptr_record :re_string ^.*$
decode_naptr_record :re_substitution_string sip:5108891234@1.8.50.14
decode_naptr_record :re_flags_string 
U_FLAG case, stopping query
new_e164_user sip:5108891234@1.8.50.14
decode_naptr_record :re_string ^.*$
decode_naptr_re
tahoe13#cord :re_substitution_string h323:5555@1.5.1.1
decode_naptr_record :re_flags_string 
U_FLAG case, stopping query
new_e164_user h323:5555@1.5.1.1
contact_list :
              sip:5108891234@1.8.50.14
contact_list :
              h323:5555@1.5.1.1
enum_resolve_domain:contact_list 64558450

A sample output of the debug voip enum summary command is shown below.

The output shows the matching number, the enum table used and the rule in the table that matched the number along with the resulting string. Note that this output is a subset of the output from debug voip enum detail command.

Router# debug voip enum summary
enum_resolve_domain:match_num 5108891234 table_indx 10
enum_resolve_domain:rule 1 result string 5108891234

The table below provides an alphabetical listing of the debug voip enum command fields and a description of each field.

Examples

The following is sample output from the debug voip event-log command:

Router# debug voip event-log
 
voip event-log debugging is on
Router#
*Jul 18 22:22:45.417: voice_elog_open: ctx_id=1F, size=4, url=
*Jul 18 22:22:45.417: lock_elog, ctx_id=1F, refcnt=1
*Jul 18 22:22:45.417: voice_elog_write:
*Jul 18 22:22:45.417: elog_write_local: message (len=143) written to elog:
1F:1058566965:584:INFO: Call setup indication received, called = 4085550198,  calling = 52927, echo canceller = enable, direct inward dialing 3953 bytes left
*Jul 18 22:22:45.417: voice_elog_write:
*Jul 18 22:22:45.417: elog_write_local: message (len=38) written to elog:
1F:1058566965:585:INFO: Dialpeer = 1 3915 bytes left
*Jul 18 22:22:45.421: voice_elog_open: ctx_id=B, size=4, url=
*Jul 18 22:22:45.421: lock_elog, ctx_id=B, refcnt=1
*Jul 18 22:22:45.421: voice_elog_write:
*Jul 18 22:22:45.421: elog_write_local: message (len=114) written to elog:
B:1058566965:586:INFO: Session started for App-type = generic, URL = tftp://demo/scripts/master/generic.vxml 3982 bytes left
*Jul 18 22:22:45.421: voice_elog_write:
*Jul 18 22:22:45.421: elog_write_local: message (len=69) written to elog:
B:1058566965:587:INFO: Incoming Telephony call received, LegID = 1F 3913 bytes left
*Jul 18 22:22:45.421: voice_elog_write:
*Jul 18 22:22:45.421: elog_write_local: message (len=89) written to elog:
B:1058566965:588:INFO: LegID = 1F: Calling = 4085550198, called = 52927, dial peer = 1 3824 bytes left
*Jul 18 22:22:45.421: voice_elog_write:
*Jul 18 22:22:45.421: elog_write_local: message (len=66) written to elog:
B:1058566965:589:INFO: LegID = 1F: Leg State = LEG_INCCONNECTED 3758 bytes left
*Jul 18 22:22:45.433: voice_elog_write:
*Jul 18 22:22:45.437: elog_write_local: message (len=42) written to elog:
1F:1058566965:590:INFO: Digit collection 3873 bytes left
*Jul 18 22:22:45.437: voice_elog_write:
*Jul 18 22:22:45.437: elog_write_local: message (len=57) written to elog:
1F:1058566965:591:INFO: Call connected using codec None 3816 bytes left
*Jul 18 22:22:45.437: voice_elog_write:
*Jul 18 22:22:45.437: elog_write_local: message (len=85) written to elog:
B:1058566965:592:INFO: Playing prompt #1: tftp://172.19.139.245/audio/ch_welcome.au 3673 bytes left
Router#
*Jul 18 22:22:55.942: voice_elog_write:
*Jul 18 22:22:55.942: elog_write_local: message (len=51) written to elog:
B:1058566975:593:ERR : Prompt play setup failure.  3622 bytes left
*Jul 18 22:22:55.942: voice_elog_write:
*Jul 18 22:22:55.942: elog_write_local: message (len=65) written to elog:
B:1058566975:594:INFO: Script received event = "error.badfetch" 3557 bytes left
*Jul 18 22:22:56.918: voice_elog_write:
*Jul 18 22:22:56.918: elog_write_local: message (len=98) written to elog: 1F:1058
Router#
566976:595:INFO: Inform application call disconnected (cause = normal call clearing (16)) 3718 bytes left
*Jul 18 22:22:56.918: voice_elog_write:
*Jul 18 22:22:56.918: elog_write_local: message (len=78) written to elog:
B:1058566976:596:INFO: Script received event = "telephone.disconnect.hangup"
 3479 bytes left
*Jul 18 22:22:56.922: voice_elog_write:
*Jul 18 22:22:56.922: elog_write_local: message (len=89) written to elog:
B:1058566976:597:INFO: LegID = 1F: Call disconnected, cause = normal call clearing (16) 3390 bytes left
*Jul 18 22:22:56.922: voice_elog_write:
*Jul 18 22:22:56.922: elog_write_local: message (len=79) written to elog:
1F:1058566976:598:INFO: Call disconnected (cause = normal call clearing (16))
 3639 bytes left
*Jul 18 22:22:56.930: voice_elog_write:
*Jul 18 22:22:56.930: elog_write_local: message (len=39) written to elog:
1F:1058566976:599:INFO: Call released
 3600 bytes left
*Jul 18 22:22:56.930: voice_elog_close, ctx_id=1F voice_elog_close, ctx_id=19
*Jul 18 22:22:56.930: unlock_elog, ctx_id=19, refcnt=0
*Jul 18 22:22:56.930: delete_elog, ctx_id=19
*Jul 18 22:22:56.930: voice_elog_write:
*Jul 18 22:22:56.930: elog_write_local: message (len=59) written to elog:
B:1058566976:600:INFO: Session done, terminating cause = 3331 bytes left
*Jul 18 22:22:56.930: voice_elog_close, ctx_id=B

Examples

The following example shows how to turn on VoIP fastpath debugging, shows how to use the show debug command to display what debugging functions are enabled, and provides sample output for the debugging function:

Router# debug voip fastpath
Fastpath related debugging is on
Router# show debug
 fastpath: 
  Fastpath related debugging is on 
Router# 
*Nov 14 08:22:35.971: NP VPD(2/01): pak sent via fastpath,part=0x652DEE80 ret=0x000003 len=32
*Nov 14 08:22:35.987: NP VPD(2/01): pak sent via fastpath,part=0x652DEEC0 ret=0x000003 len=32
*Nov 14 08:22:36.011: NP VPD(2/01): pak sent via fastpath,part=0x652DEF00 ret=0x000003 len=32
*Nov 14 08:22:36.031: NP VPD(2/01): pak sent via fastpath,part=0x652DEF40 ret=0x000003 len=32
*Nov 14 08:22:36.051: NP VPD(2/01): pak sent via fastpath,part=0x652DEF80 ret=0x000003 len=32
*Nov 14 08:22:36.071: NP VPD(2/01): pak sent via fastpath,part=0x652DEFC0 ret=0x000003 len=32
*Nov 14 08:22:36.095: NP VPD(2/01): pak sent via fastpath,part=0x652DF000 ret=0x000003 len=32
*Nov 14 08:22:36.111: NP VPD(2/01): pak sent via fastpath,part=0x652DF040 ret=0x000003 len=32
*Nov 14 08:22:36.131: NP VPD(2/01): pak sent via fastpath,part=0x652DF080 ret=0x000003 len=32
*Nov 14 08:22:36.151: NP VPD(2/01): pak sent via fastpath,part=0x652DF0C0 ret=0x000003 len=32
*Nov 14 08:22:36.171: NP VPD(2/01): pak sent via fastpath,part=0x652DF100 ret=0x000003 len=32
*Nov 14 08:22:36.195: NP VPD(2/01): pak sent via fastpath,part=0x652DF140 ret=0x000003 len=32
*Nov 14 08:22:36.207: NP VPD(2/01): pak sent via fastpath,part=0x652DF180 ret=0x000003 len=32
*Nov 14 08:22:36.231: NP VPD(2/01): pak sent via fastpath,part=0x652DF1C0 ret=0x000003 len=32 
*Nov 14 08:22:36.251: NP VPD(2/01): pak sent via fastpath,part=0x652DF200 ret=0x000003 len=32
*Nov 14 08:22:36.271: NP VPD(2/01): pak sent via fastpath,part=0x652DF240 ret=0x000003 len=32
*Nov 14 08:22:36.291: NP VPD(2/01): pak sent via fastpath,part=0x652DF280 ret=0x000003 len=32
*Nov 14 08:22:36.315: NP VPD(2/01): pak sent via fastpath,part=0x652DF2C0 ret=0x000003 len=32
*Nov 14 08:22:36.331: NP VPD(2/01): pak sent via fastpath,part=0x652DF300 ret=0x000003 len=32
*Nov 14 08:22:36.351: NP VPD(2/01): pak sent via fastpath,part=0x652DF340 ret=0x000003 len=32
*Nov 14 08:22:36.371: NP VPD(2/01): pak sent via fastpath,part=0x652DF380 ret=0x000003 len=32
*Nov 14 08:22:36.391: NP VPD(2/01): pak sent via fastpath,part=0x652DF3C0 ret=0x000003 len=32

The following example shows how to use the debug voip fastpathslot/port command to debug slot 2, port 13 on the router:

Router# debug voip fastpath 2/013
Fastpath related debugging is on 
*Nov 14 08:28:00.623: NP VPD(2/13): pak sent via fastpath,part=0x652DFFC0 ret=0x000003 len=32 
*Nov 14 08:28:00.643: NP VPD(2/13): pak sent via fastpath,part=0x652E0000 ret=0x000003 len=32 
*Nov 14 08:28:00.659: NP VPD(2/13): pak sent via fastpath,part=0x652E0080 ret=0x000003 len=32 
*Nov 14 08:28:00.831: NP VPD(2/13): pak sent via fastpath,part=0x652E0280 ret=0x000003 len=32 
*Nov 14 08:28:00.855: NP VPD(2/13): pak sent via fastpath,part=0x652E0300 ret=0x000003 len=32 
*Nov 14 08:28:00.867: NP VPD(2/13): pak sent via fastpath,part=0x652E0380 ret=0x000003 len=32 
*Nov 14 08:28:01.031: NP VPD(2/13): pak sent via fastpath,part=0x652E0540 ret=0x000003 len=32 
*Nov 14 08:28:01.051: NP VPD(2/13): pak sent via fastpath,part=0x652E0580 ret=0x000003 len=32 
*Nov 14 08:28:01.075: NP VPD(2/13): pak sent via fastpath,part=0x652E0640 ret=0x000003 len=32 
*Nov 14 08:28:01.231: NP VPD(2/13): pak sent via fastpath,part=0x652E0840 ret=0x000003 len=32 
*Nov 14 08:28:01.251: NP VPD(2/13): pak sent via fastpath,part=0x652E07C0 ret=0x000003 len=32 
*Nov 14 08:28:01.271: NP VPD(2/13): pak sent via fastpath,part=0x652E0900 ret=0x000003 len=32 
*Nov 14 08:28:01.439: NP VPD(2/13): pak sent via fastpath,part=0x652E0AC0 ret=0x000003 len=32 
*Nov 14 08:28:01.463: NP VPD(2/13): pak sent via fastpath,part=0x652E0B40 ret=0x000003 len=32 
*Nov 14 08:28:01.483: NP VPD(2/13): pak sent via fastpath,part=0x652E0BC0 ret=0x000003 len=32 

The following example shows how to enable debugging for fastpath cache invalidation on slot 2, port 17, and shows how to display sample output for the debugging function:

Router# debug voip fastpath invalidate 2/17
 
 Fastpath cache invalidation related  debugging is on
Router# show voip call summary
PORT           CODEC    VAD VTSP STATE            VPM STATE
============== ======== === ==================== ======================
6/4:0.20        g729r8    y  S_CONNECT             CSM_OC6_CONNECTED       
6/4:0.21        g729r8    y  S_CONNECT             CSM_OC6_CONNECTED       
Router# show spe | i a
Country code config : default T1 (u Law)
Country code setting: e1-default
Port state: (s)shutdown   (r)recovery  (t)test  (a)active call
            (b)busiedout  (d)download  (B)bad   (p)busyout pending
Call type : (m)modem      (d)digital   (v)voice (f)fax-relay       (_)not in use
Summary   :
Ports     : Total  540  In-use     2  Free   514  Disabled    24
Calls     : Modem    0  Digital    0  Voice    2  Fax-relay    0
                     SPE          SPE     SPE  SPE   Port         Call
SPE#    Port #       State        Busyout Shut Crash State        Type
2/02    0012-0017    ACTIVE             0    0     0 _____a       _____v      
2/03    0018-0023    ACTIVE             0    0     0 a_____       v_____      
Router# show logging
 
Syslog logging: enabled (274 messages dropped, 20 messages rate-limited,
                0 flushes, 0 overruns, xml disabled, filtering disabled)
    Console logging: disabled
    Monitor logging: level debugging, 0 messages logged, xml disabled,
                     filtering disabled
    Buffer logging: level debugging, 1018 messages logged, xml disabled,
                    filtering disabled
    Logging Exception size (8192 bytes)
    Count and timestamp logging messages: disabled
    Trap logging: level informational, 133 message lines logged
          
Log Buffer (1000000 bytes):
*Nov 14 08:40:36.499:  NP VPD (2/17): Cached header parameter values: header size : 28, payload size : 13, ssrc : 0x24DB1F03, udp chksum : 0x0
*Nov 14 08:40:36.499:  NP VPD (2/17): Cached IP/UDP pkt details: dest-ip: 31.31.31.1   src-ip: 31.31.31.3   dport: 0x4070  sport: 0x43A6
*Nov 14 08:40:40.851:  NP VPD (2/17): Cached header parameter values: header size : 28, payload size : 32, ssrc : 0x24DB1F03, udp chksum : 0x0
*Nov 14 08:40:40.851:  NP VPD (2/17): Cached IP/UDP pkt details: dest-ip: 31.31.31.1   src-ip: 31.31.31.3   dport: 0x4070  sport: 0x43A6
*Nov 14 08:40:40.939:  NP VPD (2/17): Cache being cleared due to change in payload size old payload size : 32  new rx payload size : 13 cached ssrc : 24DB1F03

Examples

The following example displays output from the debug voip fileacctcommand:

Router# debug voip fileacct
 
*May 10 06:27:43.719: : add attr:47A815E4 clid(21) 4 5000
*May 10 06:27:43.719: new list: 0x4792614C prev list: 0x47A815D0
*May 10 06:27:43.719: : add attr:47926160 dnis(22) 0 
*May 10 06:27:43.719: new list: 0x47C3A2C0 prev list: 0x4792614C
*May 10 06:27:43.719: : add attr:47C3A2D4 subscriber(106) 11 RegularLine
*May 10 06:27:43.719: new list: 0x4517FC04 prev list: 0x47C3A2C0
*May 10 06:27:43.719: : add attr:4517FC18 override_session_time(67) 4 0(0) Telephony Leg
*May 10 06:27:43.719: new list: 0x478C0CA4 prev list: 0x4517FC04
*May 10 06:27:43.719: : add attr:478C0CB8 h323-ivr-out(68) 14 Tariff:Unknown
*May 10 06:27:43.719: new list: 0x477EAFFC prev list: 0x478C0CA4
*May 10 06:27:43.719: : add attr:477EB010 h323-voice-quality(70) 1 0 
*May 10 06:27:43.719: new list: 0x4783EF80 prev list: 0x477EAFFC
*May 10 06:27:43.719: : add attr:4783EF94 gw-rxd-cgn(94) 28 ton:0,npi:0,pi:0,si:0,#:5000
*May 10 06:27:43.719: list is 466C17A8, list->featurename is 0,feat id is 11205
*May 10 06:27:43.719: fcur is 466C17A8, attr is "TWC","05/10/2007 06:27:43.695","5000","",0,11205,6510EBF8 FDF611DB A527DA52 74E8B890,2BD8,"","","",""
*May 10 06:27:43.719: : del attr47B8E814 callID(1) 4 11224(2BD8)
*May 10 06:27:43.719: : del attr45250054 cdr type(2) 4 0(0)
*May 10 06:27:43.719: : del attr452C52F0 leg type(3) 4 1(1)
*May 10 06:27:43.719: : del attr47914064 h323-conf-id(4) 35 6510EBF8 FDF611DB A527DA52 74E8B890

Examples

The raw keyword displays the raw BAS information coming from or to the DSP. It is displayed in a hexadecimal octet format. The decode option decodes the BAS information into a readable English format.

The following is sample output from the debug voip h221 raw decode command:

  BAS=81:1 0 0 0 0 0 0 1: AUDIO CAPS=g711 a-law
  BAS=82:1 0 0 0 0 0 1 0: AUDIO CAPS=g711 u-law
  BAS=84:1 0 0 0 0 1 0 0: AUDIO CAPS=g722 48k
  BAS=85:1 0 0 0 0 1 0 1: AUDIO CAPS=g728
  BAS=F9:1 1 1 1 1 0 0 1: H.242 MBE start indication
  BAS=02:0 0 0 0 0 0 1 0: H.242 MBE length=2
  BAS=0A:0 0 0 0 1 0 1 0: H.242 MBE type=H.263 caps
  BAS=8A:1 - - - - - - -: Always 1
  BAS=8A:- 0 0 0 1 - - -: H.263 MPI=1
  BAS=8A:- - - - - 0 1 -: H.263 FORMAT=h.263_cif
  BAS=8A:- - - - - - - 0: No additional options

Examples

The following is sample output from the debug voip hpi all command for an incoming ISDN call:

Router# debug voip hpi all
 
01:28:44: //-1/xxxxxxxxxxxx/HPI/[]/hpi_dspmgr_open: 

The following event shows that the HPI has identified the call, as shown by the GUID, but the call leg has not been specified, as shown by the -1 value in the CallEntry ID:

01:28:44: //-1/3FE022AC8009/HPI/[2/0:23]/hpi_dspmgr_open: 
    Allocated DSP resource: dsp_intf=0x64AF0EEC hpi_cdb=0x64ACED34 ret=1
01:28:44: //-1/3FE022AC8009/HPI/[2/0:23]/hpi_dspmgr_open: 
    Exit Line # 9411
01:28:44: //-1/3FE022AC8009/HPI/[2/0:23]/hpi_init: 
01:28:44: //-1/3FE022AC8009/HPI/[2/0:23]/hpi_init: 
    Open channel
01:28:44: //-1/3FE022AC8009/HPI/[2/0:23]/hpi_init: 
    Packet details:
      Packet Length (16), Channel Id (1), Packet Id (74)
      ALawULawSelect=A Law Associated SignalingChannel (128)
      Timeslot=0 SerialPort=0
01:28:44: //-1/3FE022AC8009/HPI/[2/0:23]/caplog_hpi_msg_log: 
01:28:44: //-1/3FE022AC8009/HPI/[2/0:23]/hpi_voice_config_params: 

For each packet-related event, information about the packet is shown following the event. The following two events show the Real-Time Protocol (RTP) packet:

01:28:44: //-1/3FE022AC8009/HPI/[2/0:23]/hpi_encap_config: 
    RTP information
01:28:44: //-1/3FE022AC8009/HPI/[2/0:23]/hpi_encap_config: 
    Packet details:
      Packet Length (38), Channel Id (1), Packet Id (92) TransportProtocol=2
      t_ssrc=0x00 r_ssrc=0x00 t_vpxcc=0x0 r_vpxcc=0x0
      sid_support=0 tse_payload=101 seq_num=0x0 redundancy=0
      cc_payload_type=0 fax_payload_type=0 alaw_pcm_switchover=0
      mulaw_pcm_switchover=0 dtmf_payload_type=0 nte_rcv_payload_type=101
01:28:44: //-1/3FE022AC8009/HPI/[2/0:23]/caplog_hpi_msg_log: 
01:28:44: //-1/3FE022AC8009/HPI/[2/0:23]/hpi_set_playout_config: 
    Packet details:
      Packet Length (18), Channel Id (1), Packet Id (76)
      Mode=1, Initial=60, Min=40, Max=200, fax_nom=300
01:28:44: //-1/3FE022AC8009/HPI/[2/0:23]/caplog_hpi_msg_log: 
01:28:44: //-1/3FE022AC8009/HPI/[2/0:23]/hpi_inband_sig: 
01:28:44: //-1/3FE022AC8009/HPI/[2/0:23]/hpi_fax_enable: 
01:28:44: //-1/3FE022AC8009/HPI/[2/0:23]/hpi_fax_enable: 
    Enable FAX
01:28:44: //-1/3FE022AC8009/HPI/[2/0:23]/hpi_fax_enable: 
    Packet details:
      Packet Length (8), Channel Id (1), Packet Id (67)
01:28:44: //-1/3FE022AC8009/HPI/[2/0:23]/caplog_hpi_msg_log: 
01:28:44: //-1/3FE022AC8009/HPI/[2/0:23]/hpi_echo_cancel: 
    Packet details:
      Packet Length (14), Channel Id (1), Packet Id (66)
      flags=0x00000B00, Threshold=-21, SuppressorCoverage=7
01:28:44: //-1/3FE022AC8009/HPI/[2/0:23]/caplog_hpi_msg_log: 
01:28:44: //-1/3FE022AC8009/HPI/[2/0:23]/hpi_idle_code_det: 
    Packet details:
      Packet Length (14), Channel Id (1), Packet Id (116)
      Enable (FALSE), Code=0x00000000, Duration (6000 ms)
01:28:44: //-1/3FE022AC8009/HPI/[2/0:23]/caplog_hpi_msg_log: 
01:28:44: //-1/3FE022AC8009/HPI/[2/0:23]/hpi_set_gain: 
    Packet details:
      Packet Length (12), Channel Id (1), Packet Id (91)
      Gain: In=0, Out=0
01:28:44: //-1/3FE022AC8009/HPI/[2/0:23]/caplog_hpi_msg_log: 
01:28:44: //-1/3FE022AC8009/HPI/[2/0:23]/hpi_cng_config: 
01:28:44: //-1/3FE022AC8009/HPI/[2/0:23]/hpi_info_field_size_config: 
01:28:44: //-1/3FE022AC8009/HPI/[2/0:23]/hpi_digit_relay_config: 
    Exit Line # 4162
01:28:44: //-1/3FE022AC8009/HPI/[2/0:23]/hpi_dspmgr_update_callid: 

At this point, the HPI identifies the call leg, as shown by the CallEntry ID changing from -1 to 11.

01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_voice_get_capabilities: 
    Exit Line # 5073
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_stop_service: 
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_idle_service: 
    Packet details:
      Packet Length (8), Channel Id (1), Packet Id (68)
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/caplog_hpi_msg_log: 
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_open_service: 
    Setting codec g729r8
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_set_codec: 
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_dsprm_callback: 
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_voice_config_params: 
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_digit_relay_config: 
    Exit Line # 4162

The RTP packet is shown again, but now more information is available, such as payload types. The packet ID identifies this as the same RTP packet shown earlier.

01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_encap_config: 
    RTP information
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_encap_config: 
    Packet details:
      Packet Length (38), Channel Id (1), Packet Id (92) TransportProtocol=2
      t_ssrc=0x040 r_ssrc=0x00 t_vpxcc=0x0 r_vpxcc=0x0
      sid_support=1 tse_payload=101 seq_num=0x13D3 redundancy=0
      cc_payload_type=125 fax_payload_type=122 alaw_pcm_switchover=8
      mulaw_pcm_switchover=0 dtmf_payload_type=121 nte_rcv_payload_type=101
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/caplog_hpi_msg_log: 
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_pak_suppress: 
    Stop packet suppression
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_pak_suppress: 
    Packet details:
      Packet Length (10), Channel Id (1), Packet Id (106)
      Mode=1
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/caplog_hpi_msg_log: 
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_vad_enable: 
    Packet details:
      Packet Length (18), Channel Id (1), Packet Id (78)
      VAD=1 (ON): Threshold=-38, VADTime=250 Aggressive=0, Noise=-62
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/caplog_hpi_msg_log: 
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_init: 
    Open channel
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_init: 
    Packet details:
      Packet Length (16), Channel Id (1), Packet Id (74)
      ALawULawSelect=A Law Associated SignalingChannel (128)
      Timeslot=0 SerialPort=0
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/caplog_hpi_msg_log: 
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_voice_config_params: 
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_encap_config: 
    RTP information
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_encap_config: 
    Packet details:
      Packet Length (38), Channel Id (1), Packet Id (92) TransportProtocol=2
      t_ssrc=0x040 r_ssrc=0x00 t_vpxcc=0x0 r_vpxcc=0x0
      sid_support=1 tse_payload=101 seq_num=0x13D3 redundancy=0
      cc_payload_type=125 fax_payload_type=122 alaw_pcm_switchover=8
      mulaw_pcm_switchover=0 dtmf_payload_type=121 nte_rcv_payload_type=101
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/caplog_hpi_msg_log: 
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_set_playout_config: 
    Packet details:
      Packet Length (18), Channel Id (1), Packet Id (76)
      Mode=1, Initial=60, Min=40, Max=200, fax_nom=300
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/caplog_hpi_msg_log: 
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_inband_sig: 

In the following several events, fax is enabled. Packets for echo cancellation, gain, voice activity detection (VAD), and other parameters appear.

01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_fax_enable: 
    Enable FAX
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_fax_enable: 
    Packet details:
      Packet Length (8), Channel Id (1), Packet Id (67)
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/caplog_hpi_msg_log: 
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_echo_cancel: 
    Packet details:
      Packet Length (14), Channel Id (1), Packet Id (66)
      flags=0x00000B00, Threshold=-21, SuppressorCoverage=7
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/caplog_hpi_msg_log: 
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_idle_code_det: 
    Packet details:
      Packet Length (14), Channel Id (1), Packet Id (116)
      Enable (FALSE), Code=0x00000000, Duration (6000 ms)
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/caplog_hpi_msg_log: 
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_set_gain: 
    Packet details:
      Packet Length (12), Channel Id (1), Packet Id (91)
      Gain: In=0, Out=0
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/caplog_hpi_msg_log: 
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_cng_config: 
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_info_field_size_config: 
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_digit_relay_config: 
    Exit Line # 4162
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_start_service: 
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_voice_mode: 
    Packet details:
      Packet Length (28), Channel Id (1), Packet Id (73)
      CodingType=20, Voice FieldSize (20), VAD Flag (250),
      EchoLength=512, ComfortNoise=1, inband_detect=0x00000001,
      DigitRelay=2, AGC Flag=0, ECAN TestGroup=0,
      ECAN TestNumber=0, DynamicPayload=0
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/caplog_hpi_msg_log: 
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_idle_code_det: 
    Packet details:
      Packet Length (14), Channel Id (1), Packet Id (116)
      Enable (FALSE), Code=0x00000000, Duration (6000 ms)
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/caplog_hpi_msg_log: 
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_start_service: 
    Exit Line # 2816
01:28:44: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_send_data_to_dsp: 
01:28:46: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_query_info: 

Transmit and receive events are shown, along with packet information.

01:28:46: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_query_tx: 
    Packet details:
      Packet Length (10), Channel Id (1), Packet Id (86)
      ResetFlag (0x00000000)
01:28:46: //11/3FE022AC8009/HPI/[2/0:23:11]/caplog_hpi_msg_log: 
01:28:46: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_query_rx: 
    Packet details:
      Packet Length (10), Channel Id (1), Packet Id (87)
      ResetFlag (0x00000000)
01:28:46: //11/3FE022AC8009/HPI/[2/0:23:11]/caplog_hpi_msg_log: 
01:28:46: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_query_pd: 
    Playout delay
01:28:46: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_query_pd: 
    Packet details:
      Packet Length (10), Channel Id (1), Packet Id (83)
      ResetFlag (0x00000000)
01:28:46: //11/3FE022AC8009/HPI/[2/0:23:11]/caplog_hpi_msg_log: 
01:28:46: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_query_pe: 
    Playout error
01:28:46: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_query_pe: 
    Packet details:
      Packet Length (10), Channel Id (1), Packet Id (84)
      ResetFlag (0x00000000)
01:28:46: //11/3FE022AC8009/HPI/[2/0:23:11]/caplog_hpi_msg_log: 
01:28:46: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_query_info: 
    Exit Line # 6578
01:28:46: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_receive_message: 
01:28:46: //11/3FE022AC8009/HPI/[2/0:23:11]/caplog_hpi_msg_log: 

Statistics for each of the events are displayed.

01:28:46: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_receive_query_tx: 
    Got TX stats 
    Packet details:
      Packet Length (36), Channel Id (1), Packet Id (199)
      TX Packets (87), Signaling Packets (0) ComfortNoise Packets (0)
      Transmit Duration (1750)
      Voice Transmit Duration (1750), FAX Transmit Duration (0)
01:28:46: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_receive_message: 
01:28:46: //11/3FE022AC8009/HPI/[2/0:23:11]/caplog_hpi_msg_log: 
01:28:46: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_receive_query_rx: 
    Got RX stats 
    Packet details:
      Packet Length (120), Channel Id (1), Packet Id (200) 
      RX Packets (5): Signaling (0), ComfortNoise (1)
      Receive Duration (1750): Voice (70) FAX (0)
      Packet Counts: OOSequence (0), Bad header (0), Late (1), Early (0)
01:28:46: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_receive_message: 
01:28:46: //11/3FE022AC8009/HPI/[2/0:23:11]/caplog_hpi_msg_log: 
01:28:46: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_receive_query_pd: 
    Got Playout Delay stats... 
    Packet details:
      Packet Length (24), Channel Id (1), Packet Id (196)
      RX Delay: CurrentEstimate=69 Low WaterMark (69) High WaterMark (70)
      Clock Offset (-279863943)
01:28:46: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_receive_message: 
01:28:46: //11/3FE022AC8009/HPI/[2/0:23:11]/caplog_hpi_msg_log: 
01:28:46: //11/3FE022AC8009/HPI/[2/0:23:11]/hpi_receive_query_pe: 
    Got Playout Error stats 
    Packet details:
      Packet Length (32), Channel Id (1), Packet Id (197)
      Predictive Concealment Duration (0)
      Interpolative Concealment Duration (0)
      Silence Concealment Duration (0)
      Retroactive Memory Update (0)
      Buffer overflow discard duration (10)
      Talkspurt Detection Errors (0)

The following sample output from the debug voip hpi checker command helps verify the operations of the HPI checker:

Router# debug voip hpi checker 
*May 19 06:30:53.532: hpi [] DSP [0/0x0] S_HPI_CLOSED(0) E_HPI_DSPRM_OPEN/SET_CODEC(54)
*May 19 06:30:53.532: hpi [] DSP [0/0x0] -> S_HPI_CLOSED(0)
*May 19 06:30:53.620: hpi [2/0:23 (22)] DSP [0/0x0] S_HPI_CLOSED(0) E_HPI_DSP_OPEN_VOICE_CHANNEL(11)
*May 19 06:30:53.620: hpi [2/0:23 (22)] DSP [0/0x0] -> S_HPI_IDLE(1)
*May 19 06:30:53.620: hpi [2/0:23 (22)] DSP [0/0x0] S_HPI_IDLE(1) E_HPI_DSPRM_OPEN/SET_CODEC(54)
*May 19 06:30:53.620: hpi [2/0:23 (22)] DSP [0/0x0] -> S_HPI_IDLE(1)
*May 19 06:30:53.624: hpi [2/0:23 (22)] DSP [0/0x0] S_HPI_IDLE(1) E_HPI_DSP_ENC_CONFIG(29)
*May 19 06:30:53.624: hpi [2/0:23 (22)] DSP [0/0x0] -> S_HPI_IDLE(1)
*May 19 06:30:53.624: hpi [2/0:23 (22)] DSP [0/0x0] S_HPI_IDLE(1) E_HPI_DSP_SET_VOICE_PLAYOUT_DELAY(13)
*May 19 06:30:53.624: hpi [2/0:23 (22)] DSP [0/0x0] -> S_HPI_IDLE(1)
*May 19 06:30:53.624: hpi [2/0:23 (22)] DSP [0/0x0] S_HPI_IDLE(1) E_HPI_DSP_IDLE_CODE_CONTROL (50)
*May 19 06:30:53.624: hpi [2/0:23 (22)] DSP [0/0x0] -> S_HPI_IDLE(1)
*May 19 06:30:53.624: hpi [2/0:23 (22)] DSP [0/0x0] S_HPI_IDLE(1) E_HPI_DSP_VOICE_MODE(10)
*May 19 06:30:53.624: hpi [2/0:23 (22)] DSP [0/0x0] -> S_HPI_VOICE(2)
*May 19 06:30:53.624: hpi [2/0:23 (22)] DSP [0/0x0] S_HPI_VOICE(2) E_HPI_DSP_GEN_PACKET_CONTROL(41)
*May 19 06:30:53.628: hpi [2/0:23 (22)] DSP [0/0x0] -> S_HPI_VOICE(2)
*May 19 06:30:53.628: hpi [2/0:23 (22)] DSP [0/0x0] S_HPI_VOICE(2) E_HPI_DSP_ECHO_CANCELLER_CONTROL(3)
*May 19 06:30:53.628: hpi [2/0:23 (22)] DSP [0/0x0] -> S_HPI_VOICE(2)
*May 19 06:30:53.628: hpi [2/0:23 (22)] DSP [0/0x0] S_HPI_VOICE(2) E_HPI_DSP_SET_GAINS(28)
*May 19 06:30:53.628: hpi [2/0:23 (22)] DSP [0/0x0] -> S_HPI_VOICE(2)
*May 19 06:30:53.628: hpi [2/0:23 (22)] DSP [0/0x0] S_HPI_VOICE(2) E_HPI_DSP_DIGIT_RELAY(22)
*May 19 06:30:53.628: hpi [2/0:23 (22)] DSP [0/0x0] -> S_HPI_VOICE(2)
*May 19 06:30:53.628: hpi [2/0:23 (22)] DSP [0/0x0] S_HPI_VOICE(2) E_HPI_DSP_VAD_ENABLE(15)
*May 19 06:30:53.628: hpi [2/0:23 (22)] DSP [0/0x0] -> S_HPI_VOICE(2)
*May 19 06:30:53.632: hpi [2/0:23 (22)] DSP [0/0x0] S_HPI_VOICE(2) E_HPI_DSP_GEN_PACKET_CONTROL(41)
*May 19 06:30:53.632: hpi [2/0:23 (22)] DSP [0/0x0] -> S_HPI_VOICE(2)
*May 19 06:30:53.632: hpi [2/0:23 (22)] DSP [0/0x0] S_HPI_VOICE(2) E_HPI_DSP_INBAND_DETECTOR_CONTROL(45)
*May 19 06:30:53.632: hpi [2/0:23 (22)] DSP [0/0x0] -> S_HPI_VOICE(2)
*May 19 06:30:53.636: hpi [2/0:23 (22)] DSP [0/0x0] S_HPI_VOICE(2) E_HPI_DSP_INBAND_DETECTOR_CONTROL(45)
*May 19 06:30:53.636: hpi [2/0:23 (22)] DSP [0/0x0] -> S_HPI_VOICE(2)
*May 19 06:30:53.624: hpi [2/0:23 (22)] DSP [0/0x0] S_HPI_IDLE(1) E_HPI_DSP_VOICE_MODE(10)
*May 19 06:30:53.624: hpi [2/0:23 (22)] DSP [0/0x0] -> S_HPI_VOICE(2)
*May 19 06:30:53.624: hpi [2/0:23 (22)] DSP [0/0x0] S_HPI_VOICE(2) E_HPI_DSP_GEN_PACKET_CONTROL(41)
*May 19 06:30:53.628: hpi [2/0:23 (22)] DSP [0/0x0] -> S_HPI_VOICE(2)
*May 19 06:30:53.628: hpi [2/0:23 (22)] DSP [0/0x0] S_HPI_VOICE(2) E_HPI_DSP_ECHO_CANCELLER_CONTROL(3)
*May 19 06:30:53.628: hpi [2/0:23 (22)] DSP [0/0x0] -> S_HPI_VOICE(2)
*May 19 06:30:53.628: hpi [2/0:23 (22)] DSP [0/0x0] S_HPI_VOICE(2) E_HPI_DSP_SET_GAINS(28)
*May 19 06:30:53.628: hpi [2/0:23 (22)] DSP [0/0x0] -> S_HPI_VOICE(2)
*May 19 06:30:53.628: hpi [2/0:23 (22)] DSP [0/0x0] S_HPI_VOICE(2) E_HPI_DSP_DIGIT_RELAY(22)
*May 19 06:30:53.628: hpi [2/0:23 (22)] DSP [0/0x0] -> S_HPI_VOICE(2)
*May 19 06:30:53.628: hpi [2/0:23 (22)] DSP [0/0x0] S_HPI_VOICE(2) E_HPI_DSP_VAD_ENABLE(15)
*May 19 06:30:53.628: hpi [2/0:23 (22)] DSP [0/0x0] -> S_HPI_VOICE(2)
*May 19 06:30:53.632: hpi [2/0:23 (22)] DSP [0/0x0] S_HPI_VOICE(2) E_HPI_DSP_GEN_PACKET_CONTROL(41)
*May 19 06:30:53.632: hpi [2/0:23 (22)] DSP [0/0x0] -> S_HPI_VOICE(2)
*May 19 06:30:53.632: hpi [2/0:23 (22)] DSP [0/0x0] S_HPI_VOICE(2) E_HPI_DSP_INBAND_DETECTOR_CONTROL(45)
*May 19 06:30:53.632: hpi [2/0:23 (22)] DSP [0/0x0] -> S_HPI_VOICE(2)
*May 19 06:30:53.636: hpi [2/0:23 (22)] DSP [0/0x0] S_HPI_VOICE(2) E_HPI_DSP_INBAND_DETECTOR_CONTROL(45)
*May 19 06:30:53.636: hpi [2/0:23 (22)] DSP [0/0x0] -> S_HPI_VOICE(2)
*May 19 06:30:56.512: hpi [2/0:23 (22)] DSP [0/0x0] S_HPI_VOICE(2) E_HPI_DSP_GET_TX_STAT(23)
*May 19 06:30:56.512: hpi [2/0:23 (22)] DSP [0/0x0] -> S_HPI_VOICE(2)
*May 19 06:30:56.512: hpi [2/0:23 (22)] DSP [0/0x0] S_HPI_VOICE(2) E_HPI_DSP_GET_RX_STAT(24)
*May 19 06:30:56.512: hpi [2/0:23 (22)] DSP [0/0x0] -> S_HPI_VOICE(2)
*May 19 06:30:56.512: hpi [2/0:23 (22)] DSP [0/0x0] S_HPI_VOICE(2) E_HPI_DSP_GET_VOICE_PLAYOUT_DELAY(20)
*May 19 06:30:56.512: hpi [2/0:23 (22)] DSP [0/0x0] -> S_HPI_VOICE(2)
*May 19 06:30:56.512: hpi [2/0:23 (22)] DSP [0/0x0] S_HPI_VOICE(2) E_HPI_DSP_GET_VOICE_PLAYOUT_ERROR(21)
*May 19 06:30:56.512: hpi [2/0:23 (22)] DSP [0/0x0] -> S_HPI_VOICE(2)
*May 19 06:30:59.384: hpi [2/0:23 (22)] DSP [0/0x0] S_HPI_VOICE(2) E_HPI_DSP_GET_TX_STAT(23)
*May 19 06:30:59.384: hpi [2/0:23 (22)] DSP [0/0x0] -> S_HPI_VOICE(2)
*May 19 06:30:59.384: hpi [2/0:23 (22)] DSP [0/0x0] S_HPI_VOICE(2) E_HPI_DSP_GET_RX_STAT(24)
*May 19 06:30:59.384: hpi [2/0:23 (22)] DSP [0/0x0] -> S_HPI_VOICE(2)
*May 19 06:30:59.384: hpi [2/0:23 (22)] DSP [0/0x0] S_HPI_VOICE(2) E_HPI_DSP_GET_VOICE_PLAYOUT_DELAY(20)
*May 19 06:30:59.384: hpi [2/0:23 (22)] DSP [0/0x0] -> S_HPI_VOICE(2)
*May 19 06:30:59.384: hpi [2/0:23 (22)] DSP [0/0x0] S_HPI_VOICE(2) E_HPI_DSP_GET_VOICE_PLAYOUT_ERROR(21)
*May 19 06:30:59.384: hpi [2/0:23 (22)] DSP [0/0x0] -> S_HPI_VOICE(2)
*May 19 06:31:06.524: hpi [2/0:23 (22)] DSP [0/0x0] S_HPI_VOICE(2) E_HPI_DSP_GEN_PACKET_CONTROL(41)
*May 19 06:31:06.524: hpi [2/0:23 (22)] DSP [0/0x0] -> S_HPI_VOICE(2)
*May 19 06:31:06.532: hpi [2/0:23 (22)] DSP [0/0x0] S_HPI_VOICE(2) E_HPI_DSP_GET_LEVELS(26)
*May 19 06:31:06.536: hpi [2/0:23 (22)] DSP [0/0x0] -> S_HPI_VOICE(2)
*May 19 06:31:06.536: hpi [2/0:23 (22)] DSP [0/0x0] S_HPI_VOICE(2) E_HPI_DSP_GET_ERROR_STAT(0)
*May 19 06:31:06.536: hpi [2/0:23 (22)] DSP [0/0x0] -> S_HPI_VOICE(2)
*May 19 06:31:06.572: hpi [2/0:23 (22)] DSP [0/0x0] S_HPI_VOICE(2) E_HPI_DSP_IDLE_MODE(5)
*May 19 06:31:06.572: hpi [2/0:23 (22)] DSP [0/0x0] -> S_HPI_IDLE(1)
*May 19 06:31:06.572: hpi [2/0:23 (22)] DSP [0/0x0] S_HPI_IDLE(1) E_HPI_DSP_CLOSE_VOICE_CHANNEL(12)
*May 19 06:31:06.572: hpi [2/0:23 (22)] DSP [0/0x0] -> S_HPI_CLOSED(0)
*May 19 06:31:06.576: hpi [2/0:23 (22)] DSP [0/0x0] -> S_HPI_CLOSED(0)
*May 19 06:31:06.576: hpi [2/0:23 (22)] DSP [0/0x0] -> S_HPI_CLOSED(0)

Examples

The following example shows debugging output from a Cisco IPIPGW:

Aug  8 15:24:30.626 EDT: cch323_build_early_fastStart_cap_response: ccb-remote_fastStart=0x63C20630
Aug  8 15:24:30.626 EDT: cch323_build_early_fastStart_cap_response:symm_mask=1,tempOtherCodec=5,templocalCodec=5,audioFastStartArray=0x63C1299C
The following line shows fast start response beginning for the inbound leg of the IP-to-IP call:
Aug  8 15:24:30.626 EDT: cch323_build_early_fastStart_cap_response: Assuming ipipgw on inbound leg.
Aug  8 15:24:30.626 EDT: Function: cch323_build_olc_for_ccapi, Line: 1198, audioFastStartArray=0x63C1299C
Aug  8 15:24:30.626 EDT: cch323_build_olc_for_ccapi: channel_info ptr=0x63C203F0, ccb ptr=0x63C18580
The following lines indicate the inbound call leg will send the channel information to the outbound call leg (not yet created):
Aug  8 15:24:30.626 EDT: cch323_build_olc_for_ccapi: Channel Information:
        Logical Channel Number (fwd/rev): 1
        Channel address (fwd/rev):        0x10C0C27
        RTP  Channel (fwd/rev):           19362
        RTCP Channel (fwd/rev):           19363
        QoS Capability (fwd/rev):         0
        Symmetric Audio Cap Mask:         0x1
        Symmetric Audio Codec Bytes:      160
        Flow Mode:                        0
        Silence Suppression:              0
Aug 8 15:24:30.626 EDT: cch323_build_olc_for_ccapi:NumOfElements = 1 idx = 1

The following line indicates the inbound call leg is set to work in IP-to-IP mode (0xF0):

Aug  8 15:24:30.630 EDT: cch323_set_h245_state_mc_mode_incoming: h245 state m/c mode=0xF0

The following line indicates flow mode for incoming call leg is set to FLOW_THROUGH (incoming callid = 35). At this point Session Application opens the outbound leg. Some output is omitted here.

Aug  8 15:24:30.630 EDT: cch323_media_flow_mode: IPIPGW(35):Flow Mode=1
Aug  8 15:24:30.630 EDT: cch323_set_h245_state_mc_mode_outgoing:call_spi_mode = 1

The following line indicates the outbound call leg is set to work in IP-to-IP mode (0xF0):

Aug  8 15:24:30.630 EDT: cch323_set_h245_state_mc_mode_outgoing: h245 state m/c mode=0xF0
Aug  8 15:24:30.630 EDT: cch323_get_peer_info line 1022:
Aug  8 15:24:30.630 EDT: cch323_get_peer_info line 1026:
Aug  8 15:24:30.630 EDT: cch323_set_pref_codec_list:IPIPGW(36):peer channel present: dp pref mask=FFFFFFFF
Aug  8 15:24:30.630 EDT: cch323_set_pref_codec_list:IPIPGW(36):first preferred codec(bytes)=5(160)

The following line indicates the outbound call leg is set to FLOW_THROUGH (outbound callid = 36):

Aug  8 15:24:30.630 EDT: cch323_get_peer_info: Flow Mode set to FLOW_THROUGH for callId 36
Aug  8 15:24:30.642 EDT: cch323_build_local_encoded_fastStartOLCs: state_mc_mode=0xF0 on outbound leg.
Aug  8 15:24:30.642 EDT: cch323_build_local_encoded_fastStartOLCs:srcAddress = 0x10C0C30, h245_lport = 0, flow mode = 1, minimum_qos=0
Aug  8 15:24:30.642 EDT: cch323_generic_open_logical_channel: IPIPGW: current codec = 5:160:160.

The following line indicates the IPIPGW received fast start response from the remote (called party) entity of the outbound call leg:

Aug  8 15:24:30.658 EDT: Function: cch323_receive_fastStart_cap_response Line: 2800
Aug  8 15:24:30.658 EDT: Function: cch323_build_olc_for_ccapi, Line: 1198, audioFastStartArray=0x63C1259C
Aug  8 15:24:30.658 EDT: cch323_build_olc_for_ccapi: channel_info ptr=0x63C12738, ccb ptr=0x631A4D68
Aug  8 15:24:30.658 EDT: cch323_build_olc_for_ccapi: Channel Information:
        Logical Channel Number (fwd/rev): 1
        Channel address (fwd/rev):        0x10C0C28
        RTP  Channel (fwd/rev):           19128
        RTCP Channel (fwd/rev):           19129
        QoS Capability (fwd/rev):         0
        Symmetric Audio Cap Mask:         0x1
        Symmetric Audio Codec Bytes:      160
        Flow Mode:                        0
        Silence Suppression:              0
Aug  8 15:24:30.658 EDT: cch323_build_olc_for_ccapi:NumOfElements = 1 idx = 1
Aug  8 15:24:30.658 EDT: Function: cch323_do_open_channel_ind Line: 1080
Aug  8 15:24:30.658 EDT: Function: cch323_open_channel_ind Line: 1132

The following lines indicates the outbound call leg (36) sends the channel response back to the inbound call leg (35) via CCAPI:

Aug  8 15:24:30.658 EDT: cch323_receive_fastStart_cap_response: callID 0x24(36), audioFastStartArray = 0x0.
Aug  8 15:24:30.658 EDT: cch323_peer_channel_ind: IPIPGW:### chn info coming in chn_ind() 
Aug  8 15:24:30.658 EDT: cch323_peer_channel_ind: IPIPGW(35):giving event to Fast start logic.
Aug  8 15:24:30.658 EDT: Function: cch323_do_open_channel Line: 5557
Aug  8 15:24:30.658 EDT: cch323_do_open_channel: line:5566, ccb->status=0x4000000
Aug  8 15:24:30.658 EDT: cch323_do_open_channel:srcAddress = 0x10C0C30, h245_lport = 18308, minimum_qos=0
Aug  8 15:24:30.658 EDT: cch323_build_fastStart_cap_response: Start...
Aug  8 15:24:30.658 EDT: cch323_build_fastStart_cap_response: selectCodec=5, codec_mask=1, configured_codecBytes=160
        forward_codecBytes=160, reverse_codecBytes=160, audioFastStartArray=0x63C1299C
Aug  8 15:24:30.658 EDT: cch323_prepare_fastStart_cap_response line 2138
Aug  8 15:24:30.658 EDT: cch323_prepare_fastStart_cap_response: callID 0x23(35), audioFastStartArray = 0x0.
Aug  8 15:24:30.658 EDT: cch323_prepare_fastStart_cap_response, ccb->local_fastStart=0x63C183C0, srcAddr=0x10C0C30, lport=18308, rport=19362, rc=1
Aug  8 15:24:30.658 EDT: cch323_build_fastStart_cap_response: local_fastStart=0x63C183C0, negotiated_codec=5, negotiated_codec_bytes=160
Aug  8 15:24:30.658 EDT: cch323_build_fastStart_cap_response: Received peer cap info. Notify RAS state machine (possible BRQ).

Outbound leg, at this point, has prepared the fast start response to be sent to the originating (calling party). This is sent in the next outgoing call control message (such as ALERT or PROGRESS):

Aug  8 15:24:30.658 EDT: cch323_build_fastStart_cap_response: Done.
Aug  8 15:24:30.658 EDT: cch323_do_open_channel: line:5644, ccb->status=0x4004200
Aug  8 15:24:30.674 EDT: cch323_h245_connection_sm: state = 0 event=5 ccb=63C18580
Aug  8 15:24:30.674 EDT: cch323_h245_connection_sm: listen state=0
Aug  8 15:24:30.678 EDT: cch323_h245_cap_ind: IPIPGW(35): masks au=0x1 data=0xC uinp=0x32.

The following line indicates the inbound call leg (35) received capability set (CAPSET) message:

Aug  8 15:24:30.678 EDT: cch323_run_h245_cap_in_sm:IPIPGW(35): got incoming CAPSET msg.
Aug  8 15:24:30.678 EDT: cch323_do_transparent_cap_ind: IPIPGW(35):mask sent to other leg=1

The following lines show the inbound call leg (35) forwarding the TCS to the outbound leg and waiting for the response of the outbound call leg (TCSACK or TCSREJ):

Aug  8 15:24:30.678 EDT: cch323_run_h245_cap_in_sm:IPIPGW(35):suppressTCS: our TCS will be sent based on peer.
Aug  8 15:24:30.678 EDT: cch323_h245_cap_notify:IPIPGW(35):not xmiting CAPSACK: wait for peer to ack.
Aug  8 15:24:30.678 EDT: cch323_caps_ind: IPIPGW(36):setting the mask to new : current mask=0x4FFFF new mask=0x1.
Aug  8 15:24:30.678 EDT: cch323_caps_ind: IPIPGW(36): ExtendedCapsPresent
Aug  8 15:24:30.678 EDT: cch323_set_dtmf_relay_mask: IPIPGW(36): extract dtmf-caps from caps struct
Aug  8 15:24:30.678 EDT: cch323_set_dtmf_relay_mask: IPIPGW(36): After extracting dtmf-caps from caps structccb->user_caps.user_input_bit_mask[0x1C]

The following line shows the outbound leg sending the TCS to the called party. No codec filter is configured on outbound dial-peer (FFFFFFFF):

Aug  8 15:24:30.678 EDT: cch323_prepare_preferred_codec_list: IPIPGW(36):munging caps:5:1:FFFFFFFF
Aug  8 15:24:30.678 EDT: cch323_prepare_preferred_codec_list: IPIPGW(36):final mask=1
Aug  8 15:24:30.678 EDT: cch323_peer_caps_ind_common:IPIPGW(36):starting 245 via tunnel
Aug  8 15:24:30.678 EDT: cch323_h245_connection_sm: state = 0 event=1 ccb=631A4D68
Aug  8 15:24:30.678 EDT: cch323_h245_connection_sm: listen state=0
Aug  8 15:24:30.678 EDT: cch323_h245_start_cap_sm: IPIPGW(36): starting the cap/msd machine.
Aug  8 15:24:30.678 EDT: cch323_send_generic_caps: IPIPGW: audiomask raw =0x1.
Aug  8 15:24:30.678 EDT: cch323_set_pref_codec_list:IPIPGW(36):first preferred codec(bytes)=21(0)

The following line shows the outbound leg forwarding the TCS over H.225 tunnel (starting H.245 via tunnel):

Aug  8 15:24:30.678 EDT: cch323_send_generic_caps: IPIPGW:[trans]audio mask after operation=0x1.

The following lines show master-slave determination events passing from inbound to outbound and vice versa:

Aug  8 15:24:30.678 EDT: cch323_run_passthru_msd: IPIPGW(36):event = H245_EVENT_MSD
Aug  8 15:24:30.678 EDT: cch323_h245_connection_sm: state = 0 event=5 ccb=63C18580
Aug  8 15:24:30.678 EDT: cch323_h245_connection_sm: listen state=0
Aug  8 15:24:30.678 EDT: cch323_run_passthru_msd: IPIPGW(35):event = H245_EVENT_MS_IND
Aug  8 15:24:30.678 EDT: cch323_h245_connection_sm: state = 2 event=5 ccb=631A4D68
Aug 8 15:24:30.678 EDT: cch323_h245_connection_sm: listen state=0
Aug  8 15:24:30.678 EDT: cch323_h245_cap_ind: IPIPGW(36): masks au=0x1 data=0xC uinp=0x32.
Aug  8 15:24:30.678 EDT: cch323_run_h245_cap_in_sm:IPIPGW(36): got incoming CAPSET msg.
Aug  8 15:24:30.678 EDT: cch323_do_transparent_cap_ind: IPIPGW(36):mask sent to other leg=1

The following lines show the outbound leg forwarding the TCS to the other leg and waiting for its response (TCSACK or TCSREJ):

Aug  8 15:24:30.678 EDT: cch323_run_h245_cap_in_sm:IPIPGW(36):suppressTCS: our TCS will be sent based on peer.
Aug 8 15:24:30.678 EDT: cch323_h245_cap_notify:IPIPGW(36):not xmiting CAPSACK: wait for peer to ack.
Aug  8 15:24:30.678 EDT: cch323_run_passthru_msd: IPIPGW(36):event = H245_EVENT_MSD
Aug  8 15:24:30.678 EDT: cch323_caps_ind: IPIPGW(35):setting the mask to new : current mask=0x4FFFF new mask=0x1.
Aug  8 15:24:30.682 EDT: cch323_caps_ind: IPIPGW(35): ExtendedCapsPresent
Aug  8 15:24:30.682 EDT: cch323_set_dtmf_relay_mask: IPIPGW(35): extract dtmf-caps from caps struct
Aug  8 15:24:30.682 EDT: cch323_set_dtmf_relay_mask: IPIPGW(35): After extracting dtmf-caps from caps structccb->user_caps.user_input_bit_mask[0x1C]
Aug  8 15:24:30.682 EDT: cch323_prepare_preferred_codec_list: IPIPGW(35):munging caps:21:1:FFFFFFFF
Aug  8 15:24:30.682 EDT: cch323_prepare_preferred_codec_list: IPIPGW(35):final mask=1
Aug  8 15:24:30.682 EDT: cch323_peer_caps_ind_common:IPIPGW(35):starting 245 via tunnel
Aug  8 15:24:30.682 EDT: cch323_h245_connection_sm: state = 0 event=1 ccb=63C18580
Aug  8 15:24:30.682 EDT: cch323_h245_connection_sm: listen state=0
Aug  8 15:24:30.682 EDT: cch323_h245_start_cap_sm: IPIPGW(35): starting the cap/msd machine.
Aug  8 15:24:30.682 EDT: cch323_send_generic_caps: IPIPGW: audiomask raw =0x1.
Aug  8 15:24:30.682 EDT: cch323_set_pref_codec_list:IPIPGW(35):first preferred codec(bytes)=21(0)

The following line shows the inbound call leg sending the TCS to the calling party:

Aug 8 15:24:30.682 EDT: cch323_send_generic_caps: IPIPGW:[trans]audio mask after operation=0x1.
Aug  8 15:24:30.682 EDT: cch323_run_passthru_msd: IPIPGW(35):event = H245_EVENT_MSD
Aug  8 15:24:30.682 EDT: cch323_h245_connection_sm: state = 2 event=5 ccb=631A4D68
Aug  8 15:24:30.682 EDT: cch323_h245_connection_sm: listen state=0
Aug  8 15:24:30.682 EDT: cch323_run_passthru_msd: IPIPGW(36):event = H245_EVENT_MS_IND
Aug  8 15:24:30.682 EDT: cch323_h245_connection_sm: state = 2 event=5 ccb=631A4D68
Aug  8 15:24:30.682 EDT: cch323_h245_connection_sm: listen state=0
Aug  8 15:24:30.682 EDT: cch323_run_h245_cap_out_sm: IPIPGW(36): got caps ack.
Aug  8 15:24:30.682 EDT: cch323_run_h245_cap_out_sm:IPIPGW(36): sending caps ack to other leg.
Aug  8 15:24:30.682 EDT: Function: cch323_do_caps_ack Line: 1116
Aug  8 15:24:30.682 EDT: cch323_run_passthru_msd: IPIPGW(35):event = H245_EVENT_MSD
Aug  8 15:24:30.682 EDT: cch323_peer_caps_ack: IPIPGW(35):sending caps resp event to CAP state mc.
Aug  8 15:24:30.682 EDT: cch323_h245_connection_sm: state = 2 event=5 ccb=631A4D68
Aug  8 15:24:30.682 EDT: cch323_h245_connection_sm: listen state=0
Aug  8 15:24:30.682 EDT: cch323_run_passthru_msd: IPIPGW(36):event = H245_EVENT_MS_CFM
Aug  8 15:24:30.682 EDT: cch323_run_passthru_msd: IPIPGW(35):event = H245_EVENT_MS_DET_RSP
Aug  8 15:24:30.686 EDT: cch323_h245_connection_sm: state = 2 event=5 ccb=63C18580
Aug  8 15:24:30.686 EDT: cch323_h245_connection_sm: listen state=0
Aug  8 15:24:30.686 EDT: cch323_run_h245_cap_out_sm: IPIPGW(35): got caps ack.

The following line shows the inbound leg informing the outbound leg of the TCSACK:

Aug 8 15:24:30.686 EDT: cch323_run_h245_cap_out_sm:IPIPGW(35): sending caps ack to other leg.
Aug  8 15:24:30.686 EDT: Function: cch323_do_caps_ack Line: 1116
Aug  8 15:24:30.686 EDT: cch323_peer_caps_ack: IPIPGW(36):sending caps resp event to CAP state mc.
Aug  8 15:24:30.686 EDT: cch323_h245_connection_sm: state = 2 event=5 ccb=63C18580
Aug  8 15:24:30.686 EDT: cch323_h245_connection_sm: listen state=0

The following lines show that master-slave determination procedures are completed on both call legs:

Aug  8 15:24:30.686 EDT: cch323_run_passthru_msd: IPIPGW(35):event = H245_EVENT_MS_CFM
Aug 8 15:24:30.686 EDT: cch323_run_passthru_msd: IPIPGW(36):event = H245_EVENT_MS_DET_RSP

Examples

The following is sample output from the debug voip lpcorcommand for a call between two phones that was blocked by LPCOR policy validation:

*Jun 25 09:52:18.910: //-1/xxxxxxxxxxxx/LPCOR/lpcor_get_index_by_name:
   lpcor local_sccp_phone_1
*Jun 25 09:52:18.910: //-1/xxxxxxxxxxxx/LPCOR/lpcor_get_index_by_name:
   lpcor local_sccp_phone_1 index 1
*Jun 25 09:52:20.114: //-1/xxxxxxxxxxxx/LPCOR/lpcor_get_index_by_peer:
   peer tag 20003, direction 1
*Jun 25 09:52:20.114: //-1/xxxxxxxxxxxx/LPCOR/lpcor_get_index_by_name:
   lpcor local_sccp_phone_2
*Jun 25 09:52:20.114: //-1/xxxxxxxxxxxx/LPCOR/lpcor_get_index_by_name:
   lpcor local_sccp_phone_2 index 2
*Jun 25 09:52:20.114: //-1/xxxxxxxxxxxx/LPCOR/lpcor_get_index_by_peer:
   Return Lpcor Index 2 for Peer Tag 20003 *Jun 25 09:52:20.114: //-1/xxxxxxxxxxxx/LPCOR/lpcor_index_is_valid:
   lpcor index 1 is valid
*Jun 25 09:52:20.114: //-1/xxxxxxxxxxxx/LPCOR/lpcor_policy_validate:
   Source LPCOR Index=1, Target LPCOR Policy=local_sccp_phone_2  -Traceback= 0x42949584 0x4219C430 0x4219CCDC 0x421A6B60 0x421A6D1C 0x421A75EC 0x421AB328 0x421ACA14 0x421B2518 0x421B2FFC 0x421B7614 0x4217F910 0x421F522C 0x421F89CC 0x421D84FC 0x422033BC *Jun 25 09:52:20.118: //-1/xxxxxxxxxxxx/LPCOR/lpcor_policy_validate:
   Validate Fail; lpcor (source[1] target[2])

Examples

Output has been omitted due to its large volume.

Examples

The following is sample output from the debug voip profile help command:

Router# debug voip profile help
 
"debug voip profile modem relay signaling" includes:
   debug csm voice
   debug isdn q931
   debug cdapi detail
   debug cdapi events
   debug voip dspapi all
   debug voip hpi all
   debug voip vtsp all
   debug voip tsp all
   debug voip ccapi all
   debug cch323 all
   debug ccsip error
   debug ccsip messages
   debug mgcp errors
   debug mgcp events
   debug mgcp media
   debug mgcp packets
   debug mgcp voipcac
   debug voip dsm all
 
"debug voip profile voice application" includes:
   debug voip dialpeer all
   debug voip ccapi all
   debug voip ivr all
   debug voip application all
   debug voip application vxml all
 
"debug voip profile [ voice | modem pass-through ] signaling" includes:
   debug csm voice
   debug isdn q931
   debug cdapi detail
   debug cdapi events
   debug h225 asn1
   debug h225 events
   debug h225 q931
   debug h245 events
   debug h245 asn1
   debug voip dspapi all
   debug voip hpi all
   debug voip vtsp all
   debug voip tsp all
   debug voip ccapi all
   debug cch323 all
   debug rtpspi all
   debug ccsip error
   debug ccsip messages
   debug mgcp errors
   debug mgcp events
   debug mgcp media
   debug mgcp packets
   debug mgcp voipcac
   debug voip rawmsg
   debug gtd error
   debug gtd events
   debug voip dsm all
 
"debug voip profile fax mail" includes:
   debug csm voice
   debug isdn q931
   debug voip dspapi all
   debug voip hpi all
   debug voip vtsp all
   debug voip ccapi all
   debug voip ivr all
   debug voip application all
   debug voip application vxml all
   debug fmail client
   debug fmail server
   debug fax mta all
   debug fax receive all
   debug fax send all
   debug text-to-fax
   debug tiff reader
   debug tiff writer
   debug fax mmoip aaa
   debug voip dsm all
 
"debug voip profile fax relay application" includes:
   debug voip dialpeer all
   debug voip ccapi all
   debug voip ivr all
   debug voip application all
   debug voip application vxml all
 
"debug voip profile fax relay signaling" includes:
   debug csm voice
   debug isdn q931
   debug cdapi detail
   debug cdapi events
   debug h225 asn1
   debug h225 events
   debug h225 q931
   debug h245 events
   debug h245 asn1
   debug voip dspapi all
   debug voip hpi all
   debug voip vtsp all
   debug voip tsp all
   debug voip ccapi all
   debug cch323 all
   debug rtpspi all
   debug ccsip error
   debug ccsip messages
   debug mgcp errors
   debug mgcp events
   debug mgcp media
   debug mgcp packets
   debug mgcp voipcac
   debug voip rawmsg
   debug gtd error
   debug gtd events

Examples

Output has been omitted due to its large volume.

Examples

Output has been omitted due to its large volume.

Examples

The following is sample output from the debug voip rawmsgcommand:

Router# debug voip rawmsg
voip rawmsg debugging is on
Router#
*Mar  1 01:16:25.155: //-1/xxxxxxxxxxxx/CCAPI/ccAllocRawMsgInfo: VoIP Raw Msg Al
loc from 1, Length 18 Body 638E0C5

These debug messages show that a raw message is allocated for this call. The pointer to the memory location for this raw message is 63075164.

*Mar  1 01:16:25.155: //-1/xxxxxxxxxxxx/CCAPI/ccAllocRawMsgInfo: Raw Message ALL
OCATED: ptr is 63075164, owner is 1, length is 18, msg is 638E0C54, type is 0, p
rotocol id is 0

The call control API (CCAPI) gets a setup indicator. It has no information about the callid (-1) and GUID (xxxxxxxxxxxx).

*Mar  1 01:16:25.159: //-1/xxxxxxxxxxxx/CCAPI/cc_api_call_setup_ind:
*Mar  1 01:16:25.159: Raw Message MaMa is TSP owner is CCAPI, length is 77, ptr
is 63075164, type is 0, protocol id is 2

The SSAPP at this stage knows about the CallEntry ID (30) but not about GUID (xxxxxxxxx) or the dial-peer (-1).

*Mar  1 01:16:25.163: //30/xxxxxxxxxxxx/SSAPP:-1:-1/ssaCallSetupInd:
*Mar  1 01:16:25.163: Raw Message MaMa is TSP owner is SSAPP, length is 77, ptr
is 63075164, type is 0, protocol id is 2

The SSAPP learns about the GUID (34C457CD802F) and also learns the incoming dial peer (10002).

*Mar  1 01:16:25.163: //30/34C457CD802F/SSAPP:10002:-1/ssaSetupPeer:
*Mar  1 01:16:25.163: Raw Message MaMa is TSP owner is SSAPP, length is 77, ptr
is 63075164, type is 0, protocol id is 2

The CCAPI gets the call proceeding for CallEntry ID 30. CCAPI still does not have a GUID (xxxxxxxxxxx).

*Mar  1 01:16:25.163: //30/xxxxxxxxxxxx/CCAPI/ccCallProceeding:

A new raw message buffer is created and the previous one is released.

*Mar  1 01:16:25.163: //-1/xxxxxxxxxxxx/CCAPI/ccAllocRawMsgInfo: VoIP Raw Msg Al
loc from 10, Length 77 Body 0
*Mar  1 01:16:25.167: //-1/xxxxxxxxxxxx/CCAPI/ccAllocRawMsgInfo: Raw Message ALL
OCATED: ptr is 630751EC, owner is 10, length is 77, msg is 638E0F0C, type is 0,
protocol id is 0
*Mar  1 01:16:25.167: //30/34C457CD802F/SSAPP:10002:-1/ssaSetupPeer:
*Mar  1 01:16:25.167: ssaSetupPeer: Saved rawmsgpp 630751EC len 77
IAM,
GCI,34c457cd14f911cc802f95f5fabb6b0f?)??p?34999
*Mar  1 01:16:25.167: //30/xxxxxxxxxxxx/CCAPI/ccCallSetupRequest:
*Mar  1 01:16:25.167: Raw Message MaMa is TSP owner is SSAPP, length is 77, ptr
is 63075164, type is 0, protocol id is 2
*Mar  1 01:16:25.167: //-1/xxxxxxxxxxxx/CCAPI/ccIFCallSetupRequestPrivate:
*Mar  1 01:16:25.167: Raw Message MaMa is TSP owner is SSAPP, length is 77, ptr
is 63075164, type is 0, protocol id is 2

The SSAPP gets a message indicating the digits were passed along the VoIP call leg to the terminating gateway. The CallEntry ID is 30, GUID is 34C457CD802F and the incoming dial peer is 10002.

*Mar  1 01:16:25.167: //30/34C457CD802F/SSAPP:10002:-1/ssaReportDigitsDone:
The old raw message 63075164 was freed. The new one is 630751EC.
*Mar  1 01:16:25.179: //-1/xxxxxxxxxxxx/CCAPI/ccFreeRawMsgInfo:
Router#Raw Message FREED: ptr is 63075164, owner is 3, length is 4D, msg is 638E
0DB0, type is 0, protocol id is 2

CCAPI got a call proceeding on the second call leg (31); it has no information about the GUID (xxxxxxxxx).

*Mar  1 01:16:25.223: //31/xxxxxxxxxxxx/CCAPI/cc_api_call_proceeding:

CCAPI got a call alert on the second call leg (31); still no information about the GUID (xxxxxxxxx).

*Mar  1 01:16:25.227: //31/xxxxxxxxxxxx/CCAPI/cc_api_call_alert:

The alert is sent to the first call leg (30), GUID 34C457CD802F.

*Mar  1 01:16:25.227: //30/34C457CD802F/SSAPP:10002:-1/ssaAlert:
*Mar  1 01:16:25.227: //30/xxxxxxxxxxxx/CCAPI/ccCallAlert:
The call is answered at this point and the CCAPI gets a call connect for the second call leg (CallEntry ID is 31; GUID is xxxxxxxxx).
*Mar  1 01:16:40.975: //31/xxxxxxxxxxxx/CCAPI/cc_api_call_connected:

The call connect is sent to the first call leg (30), GUID 34C457CD802F.

*Mar  1 01:16:40.975: //30/34C457CD802F/SSAPP:10002:-1/ssaConnect:
*Mar  1 01:16:40.975: //30/xxxxxxxxxxxx/CCAPI/ccCallConnect:

The current raw message (ptr 630751EC) is released; a new one will be proclaimed when needed.

*Mar  1 01:16:40.975: //-1/xxxxxxxxxxxx/CCAPI/ccFreeRawMsgInfo: Raw Message FREE
D: ptr is 630751EC, owner is 10, length is 4D, msg is 638E0F0C, type is 0, 
protocol id is 2

A new raw message (ptr 63075274) is proclaimed.

*Mar  1 01:17:04.007: //-1/xxxxxxxxxxxx/CCAPI/ccAllocRawMsgInfo: VoIP Raw Msg Al
loc from 1, Length 4 Body 638E1068
*Mar  1 01:17:04.007: //-1/xxxxxxxxxxxx/CCAPI/ccAllocRawMsgInfo: Raw Message ALL
OCATED: ptr is 63075274, owner is 1, length is 4, msg is 638E1068, type is 0, protocol id is 0

The call terminates now. CCAPI detects a call disconnect from the first call leg (30) with no GUID (xxxxxxxxx).

*Mar  1 01:17:04.007: //30/xxxxxxxxxxxx/CCAPI/cc_api_call_disconnected:
*Mar  1 01:17:04.007: Raw Message MaMa is TSP owner is CCAPI, length is 4, ptr i
s 63075274, type is 0, protocol id is 2

The disconnect is sent to the first call leg (30), GUID (34C457CD802F).

*Mar  1 01:17:04.011: //30/34C457CD802F/SSAPP:10002:14/ssaDisconnected:
*Mar  1 01:17:04.011: Raw Message MaMa is TSP owner is SSAPP, length is 4, ptr i
s 63075274, type is 0, protocol id is 2

The CCAPI disconnects both call legs (incoming 30 and outgoing 31).

*Mar  1 01:17:04.011: //30/xxxxxxxxxxxx/CCAPI/ccCallDisconnect:
*Mar  1 01:17:04.011: //31/xxxxxxxxxxxx/CCAPI/ccCallDisconnect:
*Mar  1 01:17:04.011: Raw Message MaMa is TSP owner is SSAPP, length is 4, ptr i
s 63075274, type is 0, protocol id is 2

The raw message is released.

*Mar  1 01:17:04.015: //-1/xxxxxxxxxxxx/CCAPI/ccFreeRawMsgInfo: Raw Message FREE
D: ptr is 63075274, owner is 3, length is 4, msg is 638E1068, type is 0, protocol id is 2

The following example shows output when you use the debug voip rawmsg detail command. This example shows that the CCAPI layer received an indication for call setup. The detailed raw message dumps the hex of the message. This output is used to track down data pointing to different variables within the software modules.

Router# debug voip rawmsg detail
*Mar  6 17:03:24.169://-1/xxxxxxxxxxxx/CCAPI/ccAllocRawMsgInfo:VoIP Raw Msg Al
loc from 5, Length 0 Body 0
*Mar  6 17:03:24.173://-1/xxxxxxxxxxxx/CCAPI/cc_api_call_setup_ind:
*Mar  6 17:03:24.173:Raw Message MaMa is CCAPI owner is CCAPI, length is 59, ptr is 63045C14, type is 0, protocol id is 18
*Mar  6 17:03:24.173:Raw Message is :1C 39 9E 01 00 03 67 74 64 00 00 00 2E 49
 41 4D 2C 0D 0A 47 43 49 2C 35 33 39 61 30 35 39 64 31 39 36 62 31 31 63 63 38 3
9 30 63 39 30 37 65 31 65 31 37 35 61 34 37 0D 0A 0D 0A

Examples

The following is sample output from the debug voip rtcp command:

Router# debug voip rtcp
1w0d: voip_rtcp_create_session: callID=37, dstCallID=36 laddr=172.19.169.85, lp0
1w0d: voip_rtcp_get_cname: cname=0.0.0@172.19.169.85
1w0d: voip_rtcp_send_event: event=EV_NEW
1w0d: voip_rtcp_new: rtcp_interval=1893
Router#
1w0d: voip_rtcp_send_event: event=EV_STATS
1w0d: voip_rtcp_stats_req: rtcp_interval=3448
1w0d: voip_rtcp_stats_req:delay=45 lost_packets=0 rtt=0 
Router#
1w0d: recv:
1w0d: SR: ssrc=0x1272A94D sr_ntp_h=0xAF44E045 sr_ntp_l=0xA6CE39C sr_timestamp=02
1w0d: SDES: ssrc=0x1272A94D name=1 len=19 data=0.0.0@172.19.169.77
1w0d: rtcp_round_trip_delay: ssrc=0x1D86A955
Router#
1w0d: voip_rtcp_send_event: event=EV_STATS
1w0d: voip_rtcp_stats_req: rtcp_interval=6394
1w0d: voip_rtcp_stats_req:delay=40 lost_packets=0 rtt=0 
1w0d: recv:
1w0d: SR: ssrc=0x1272A94D sr_ntp_h=0xAF44E047 sr_ntp_l=0xFFB007F6 sr_timestamp=6
1w0d: SDES: ssrc=0x1272A94D name=1 len=19 data=0.0.0@172.19.169.77
1w0d: rtcp_round_trip_delay: ssrc=0x1D86A955
Router#
1w0d: voip_rtcp_remove_ccb
1w0d: voip_rtcp_send_event: event=EV_DESTROY
1w0d: voip_rtcp_destroy_idle
1w0d: voip_rtcp_close_session
1w0d: Cleaning up sess=62F95F58, sp=19544, dp=17130