Tuesday, November 27, 2012

Cisco VoIP Gateway: Watching A SIP Call Come Into The H323 Gateway

Have you ever needed to see if a call was coming in on your SIP trunk so that you could verify that the call was actually getting to your gateway?  Well, I did today to troubleshoot an issue on our hosted VoIP solution.  Here is what I did on the Cisco router to do some troubleshooting:
debug ccsip messages
debug voip ccapi inout
term mon
conf t
logg mon
logg on
exit

With these commands in place, I placed the call in and verified that the call actually did come in.
Calling number is 205.555.1234
Called number is 205.444.5678
2.2.2.2, 3.3.3.3, and 4.4.4.4 represent the SIP carrier.
10.10.10.10 represents my gateway

Here is the capture.  I just think its interesting:
101892: .Nov 27 17:33:05.026: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
INVITE sip:2054445678@10.10.10.10:5060 SIP/2.0
Via: SIP/2.0/UDP 2.2.2.2:5060;branch=z9hG4bK05Bbcbd728f10b75fab
From: "KILLEN,SHANE" <sip:2055551234@2.2.2.2;pstn-params=9084818088;cpc=ordinary>;tag=gK054ac3ea
To: <sip:2054445678@10.10.10.10>
Call-ID: 990183475_22697175@2.2.2.2
CSeq: 10426 INVITE
Max-Forwards: 66
Allow: INVITE,ACK,CANCEL,BYE,REGISTER,REFER,INFO,SUBSCRIBE,NOTIFY,PRACK,UPDATE,OPTIONS
Accept: application/sdp, application/isup, application/dtmf, application/dtmf-relay,  multipart/mixed
Contact: "KILLEN,SHANE" <sip:2055551234@2.2.2.2:5060>
Remote-Party-ID: "KILLEN,SHANE" <sip:2055551234@2.2.2.2:5060>;privacy=off
Supported: timer
Session-Expires: 1800
Min-SE: 90
Content-Length:  305
Content-Disposition: session; handling=required
Content-Type: application/sdp

v=0
o=Sonus_UAC 25520 6934 IN IP4 2.2.2.2
s=SIP Media Capabilities
c=IN IP4 3.3.3.3
t=0 0
m=audio 24546 RTP/AVP 0 18 8 101
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv
a=ptime:20

101893: .Nov 27 17:33:05.038: //46270/xxxxxxxxxxxx/CCAPI/cc_api_caps_ind:
   Call Entry Is Not Found
101894: .Nov 27 17:33:05.038: //-1/55C5A9C7B288/CCAPI/cc_api_display_ie_subfields:
   cc_api_call_setup_ind_common:
   cisco-username=2055551234
   ----- ccCallInfo IE subfields -----
   cisco-ani=sip:2055551234@2.2.2.2;pstn-params=9084818088;cpc=ordinary
   cisco-anitype=0
   cisco-aniplan=0
   cisco-anipi=0
   cisco-anisi=0
   dest=sip:2054445678@10.10.10.10:5060
   cisco-desttype=0
   cisco-destplan=0
   cisco-rdie=FFFFFFFF
   cisco-rdn=
   cisco-rdntype=0
   cisco-rdnplan=0
   cisco-rdnpi=-1
   cisco-rdnsi=-1
   cisco-redirectreason=-1   fwd_final_type =0
   final_redirectNumber =
   hunt_group_timeout =0

101895: .Nov 27 17:33:05.042: //-1/55C5A9C7B288/CCAPI/cc_api_call_setup_ind_common:
   Interface=0x471F0134, Call Info(
   Calling Number=sip:2055551234@2.2.2.2;pstn-params=9084818088;cpc=ordinary,(Calling Name=)(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed),
   Called Number=sip:2054445678@10.10.10.10:5060(TON=Unknown, NPI=Unknown),
   Calling Translated=FALSE, Subscriber Type Str=Unknown, FinalDestinationFlag=TRUE,
   Incoming Dial-peer=16, Progress Indication=NULL(0), Calling IE Present=TRUE,
   Source Trkgrp Route Label=, Target Trkgrp Route Label=, CLID Transparent=FALSE), Call Id=46270
101896: .Nov 27 17:33:05.042: //-1/55C5A9C7B288/CCAPI/ccCheckClipClir:
   In: Calling Number=sip:2055551234@2.2.2.2;pstn-params=9084818088;cpc=ordinary(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
101897: .Nov 27 17:33:05.042: //-1/55C5A9C7B288/CCAPI/ccCheckClipClir:
   Out: Calling Number=sip:2055551234@2.2.2.2;pstn-params=9084818088;cpc=ordinary(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
101898: .Nov 27 17:33:05.042: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
101899: .Nov 27 17:33:05.042: :cc_get_feature_vsa malloc success
101900: .Nov 27 17:33:05.042: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
101901: .Nov 27 17:33:05.042:  cc_get_feature_vsa count is 5
101902: .Nov 27 17:33:05.042: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
101903: .Nov 27 17:33:05.042: :FEATURE_VSA attributes are: feature_name:0,feature_time:1185232256,feature_id:46019
101904: .Nov 27 17:33:05.046: //46270/55C5A9C7B288/CCAPI/cc_api_call_setup_ind_common:
   Set Up Event Sent;
   Call Info(Calling Number=(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed),
   Called Number=(TON=Unknown, NPI=Unknown))
101905: .Nov 27 17:33:05.050: //46270/55C5A9C7B288/CCAPI/cc_process_call_setup_ind:
   Event=0x4735E310
101906: .Nov 27 17:33:05.050: //46270/55C5A9C7B288/CCAPI/ccCallSetContext:
   Context=0x47CFA438
101907: .Nov 27 17:33:05.050: //46270/55C5A9C7B288/CCAPI/cc_process_call_setup_ind:
   >>>>CCAPI handed cid 46270 with tag 16 to app "_ManagedAppProcess_Default"
101908: .Nov 27 17:33:05.054: //46270/55C5A9C7B288/CCAPI/ccCallProceeding:
   Progress Indication=NULL(0)
101909: .Nov 27 17:33:05.054: //-1/xxxxxxxxxxxx/CCAPI/ccGetMemPoolFromContainer:
   mempool not found from usrContainer(47BBA098)
101910: .Nov 27 17:33:05.054: //-1/xxxxxxxxxxxx/CCAPI/ccCreateMemPoolInContainer:
   Mempool(46A266E0) created in usrContainer(47BBA098)
101911: .Nov 27 17:33:05.058: //46270/55C5A9C7B288/CCAPI/ccCallSetupRequest:
   Destination=, Calling IE Present=TRUE, Mode=0,
   Outgoing Dial-peer=111, Params=0x45C360DC, Progress Indication=NULL(0)
101912: .Nov 27 17:33:05.058: //46270/55C5A9C7B288/CCAPI/ccCheckClipClir:
   In: Calling Number=sip:2055551234@2.2.2.2;pstn-params=9084818088;cpc=ordinary(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
101913: .Nov 27 17:33:05.058: //46270/55C5A9C7B288/CCAPI/ccCheckClipClir:
   Out: Calling Number=sip:2055551234@2.2.2.2;pstn-params=9084818088;cpc=ordinary(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
101914: .Nov 27 17:33:05.058: //46270/55C5A9C7B288/CCAPI/ccCallSetupRequest:
   Destination Pattern=20571669.., Called Number=2054445678, Digit Strip=FALSE
101915: .Nov 27 17:33:05.058: //46270/55C5A9C7B288/CCAPI/ccCallSetupRequest:
   Calling Number=sip:2055551234@2.2.2.2;pstn-params=9084818088;cpc=ordinary(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed),
   Called Number=2054445678(TON=Unknown, NPI=Unknown),
   Redirect Number=, Display Info=KILLEN,SHANE
   Account Number=2055551234, Final Destination Flag=TRUE,
   Guid=55C5A9C7-37EF-11E2-B288-D61E695CAF39, Outgoing Dial-peer=111
101916: .Nov 27 17:33:05.058: //46270/55C5A9C7B288/CCAPI/cc_api_display_ie_subfields:
   ccCallSetupRequest:
   cisco-username=2055551234
   ----- ccCallInfo IE subfields -----
   cisco-ani=sip:2055551234@2.2.2.2;pstn-params=9084818088;cpc=ordinary
   cisco-anitype=0
   cisco-aniplan=0
   cisco-anipi=0
   cisco-anisi=0
   dest=2054445678
   cisco-desttype=0
   cisco-destplan=0
   cisco-rdie=FFFFFFFF
   cisco-rdn=
   cisco-rdntype=0
   cisco-rdnplan=0
   cisco-rdnpi=-1
   cisco-rdnsi=-1
   cisco-redirectreason=-1   fwd_final_type =0
   final_redirectNumber =
   hunt_group_timeout =0

101917: .Nov 27 17:33:05.062: //46270/55C5A9C7B288/CCAPI/ccIFCallSetupRequestPrivate:
   Interface=0x46F4AAA8, Interface Type=1, Destination=, Mode=0x0,
   Call Params(Calling Number=sip:2055551234@2.2.2.2;pstn-params=9084818088;cpc=ordinary,(Calling Name=KILLEN,SHANE)(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed),
   Called Number=2054445678(TON=Unknown, NPI=Unknown), Calling Translated=FALSE,
   Subscriber Type Str=Unknown, FinalDestinationFlag=TRUE, Outgoing Dial-peer=111, Call Count On=FALSE,
   Source Trkgrp Route Label=, Target Trkgrp Route Label=, tg_label_flag=0, Application Call Id=)
101918: .Nov 27 17:33:05.062: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
  101919: .Nov 27 17:33:05.062: :cc_get_feature_vsa malloc success
101920: .Nov 27 17:33:05.062: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
  101921: .Nov 27 17:33:05.062:  cc_get_feature_vsa count is 6
101922: .Nov 27 17:33:05.062: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
  101923: .Nov 27 17:33:05.062: :FEATURE_VSA attributes are: feature_name:0,feature_time:1185229664,feature_id:46020
101924: .Nov 27 17:33:05.062: //46271/55C5A9C7B288/CCAPI/ccIFCallSetupRequestPrivate:
   SPI Call Setup Request Is Success; Interface Type=1, FlowMode=1
101925: .Nov 27 17:33:05.062: //46271/55C5A9C7B288/CCAPI/ccCallSetContext:
   Context=0x45C3608C
101926: .Nov 27 17:33:05.062: //46270/55C5A9C7B288/CCAPI/ccSaveDialpeerTag:
   Outgoing Dial-peer=111
101927: .Nov 27 17:33:05.074: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 2.2.2.2:5060;branch=z9hG4bK05Bbcbd728f10b75fab
From: "KILLEN,SHANE" <sip:2055551234@2.2.2.2;pstn-params=9084818088;cpc=ordinary>;tag=gK054ac3ea
To: <sip:2054445678@10.10.10.10>
Date: Tue, 27 Nov 2012 17:33:05 GMT
Call-ID: 990183475_22697175@2.2.2.2
CSeq: 10426 INVITE
Allow-Events: telephone-event
Server: Cisco-SIPGateway/IOS-12.x
Content-Length: 0

101928: .Nov 27 17:33:05.082: //46271/55C5A9C7B288/CCAPI/cc_api_set_called_ccm_detected:
   CallInfo(called ccm detected=TRUE ccmVersion 3)
101929: .Nov 27 17:33:05.082: //46271/55C5A9C7B288/CCAPI/cc_api_call_proceeding:
   Interface=0x46F4AAA8, Progress Indication=NULL(0)
101930: .Nov 27 17:33:05.082: //46271/55C5A9C7B288/CCAPI/cc_api_call_disconnected:
   Cause Value=27, Interface=0x46F4AAA8, Call Id=46271
101931: .Nov 27 17:33:05.082: //46271/55C5A9C7B288/CCAPI/cc_api_call_disconnected:
   Call Entry(Responsed=TRUE, Cause Value=27, Retry Count=0)
101932: .Nov 27 17:33:05.086: //46270/xxxxxxxxxxxx/CCAPI/ccCallReleaseResources:
   release reserved xcoding resource.
101933: .Nov 27 17:33:05.086: //46271/55C5A9C7B288/CCAPI/ccCallSetAAA_Accounting:
   Accounting=0, Call Id=46271
101934: .Nov 27 17:33:05.086: //46271/55C5A9C7B288/CCAPI/ccCallDisconnect:
   Cause Value=27, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=27)
101935: .Nov 27 17:33:05.086: //46271/55C5A9C7B288/CCAPI/ccCallDisconnect:
   Cause Value=27, Call Entry(Responsed=TRUE, Cause Value=27)
101936: .Nov 27 17:33:05.086: //46271/55C5A9C7B288/CCAPI/cc_api_get_transfer_info:
   Transfer Number Is Null
101937: .Nov 27 17:33:05.086: %VOIPAAA-5-VOIP_CALL_HISTORY: CallLegType 2, ConnectionId 55C5A9C737EF11E2B288D61E695CAF39, SetupTime .17:33:05.066 UTC Tue Nov 27 2012, PeerAddress 2054445678, PeerSubAddress , DisconnectCause 1B  , DisconnectText destination out of order (27), ConnectTime .17:33:05.086 UTC Tue Nov 27 2012, DisconnectTime .17:33:05.086 UTC Tue Nov 27 2012, CallOrigin 1, ChargedUnits 0, InfoType 2, TransmitPackets 0, TransmitBytes 0, ReceivePackets 0, ReceiveBytes 0
101938: .Nov 27 17:33:05.090: //-1/xxxxxxxxxxxx/CCAPI/cc_build_feature_vsa:
  101939: .Nov 27 17:33:05.090: :Inside cc_build_feature_vsa
101940: .Nov 27 17:33:05.090: //-1/xxxxxxxxxxxx/CCAPI/cc_build_feature_vsa:
  101941: .Nov 27 17:33:05.090:  feature call basic
101942: .Nov 27 17:33:05.090: //-1/xxxxxxxxxxxx/CCAPI/cc_build_feature_vsa:
  101943: .Nov 27 17:33:05.090: cc_build_feature_vsa attr is fn:TWC,ft:11/27/2012 17:33:05.062,cgn:2055551234,cdn:2054445678,frs:0,fid:46020,fcid:55C5A9C737EF11E2B288D61E695CAF39,legID:B4BF
101944: .Nov 27 17:33:05.090: %VOIPAAA-5-VOIP_FEAT_HISTORY: FEAT_VSA=fn:TWC,ft:11/27/2012 17:33:05.062,cgn:2055551234,cdn:2054445678,frs:0,fid:46020,fcid:55C5A9C737EF11E2B288D61E695CAF39,legID:B4BF,bguid:55C5A9C737EF11E2B288D61E695CAF39
101945: .Nov 27 17:33:05.094: //46271/55C5A9C7B288/CCAPI/cc_api_call_disconnect_done:
   Disposition=0, Interface=0x46F4AAA8, Tag=0x0, Call Id=46271,
   Call Entry(Disconnect Cause=27, Voice Class Cause Code=0, Retry Count=0)
101946: .Nov 27 17:33:05.094: //46271/55C5A9C7B288/CCAPI/cc_api_call_disconnect_done:
   Call Disconnect Event Sent
101947: .Nov 27 17:33:05.094: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
  101948: .Nov 27 17:33:05.094: :cc_free_feature_vsa freeing 46A52B58
101949: .Nov 27 17:33:05.094: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
  101950: .Nov 27 17:33:05.094:  vsacount in free is 5
101951: .Nov 27 17:33:05.098: //-1/xxxxxxxxxxxx/CCAPI/ccMemPoolTDFreeHelper:
   data = 47BD4924
101952: .Nov 27 17:33:05.098: ccMemPoolTDFreeHelper:mem_mgr_mempool_free: mem_refcnt(46A266E0)=0 - mempool cleanup
101953: .Nov 27 17:33:05.098: //46270/55C5A9C7B288/CCAPI/ccCallDisconnect:
   Cause Value=27, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=0)
101954: .Nov 27 17:33:05.098: //46270/55C5A9C7B288/CCAPI/ccCallDisconnect:
   Cause Value=27, Call Entry(Responsed=TRUE, Cause Value=27)
101955: .Nov 27 17:33:05.102: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 404 Not Found
Via: SIP/2.0/UDP 2.2.2.2:5060;branch=z9hG4bK05Bbcbd728f10b75fab
From: "KILLEN,SHANE" <sip:2055551234@2.2.2.2;pstn-params=9084818088;cpc=ordinary>;tag=gK054ac3ea
To: <sip:2054445678@10.10.10.10>;tag=ECFD05A0-65
Date: Tue, 27 Nov 2012 17:33:05 GMT
Call-ID: 990183475_22697175@2.2.2.2
CSeq: 10426 INVITE
Allow-Events: telephone-event
Server: Cisco-SIPGateway/IOS-12.x
Reason: Q.850;cause=27
Content-Length: 0

101956: .Nov 27 17:33:05.154: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
ACK sip:2054445678@10.10.10.10:5060 SIP/2.0
Via: SIP/2.0/UDP 2.2.2.2:5060;branch=z9hG4bK05Bbcbd728f10b75fab
From: "KILLEN,SHANE" <sip:2055551234@2.2.2.2;pstn-params=9084818088;cpc=ordinary>;tag=gK054ac3ea
To: <sip:2054445678@10.10.10.10>;tag=ECFD05A0-65
Call-ID: 990183475_22697175@2.2.2.2
CSeq: 10426 ACK
Max-Forwards: 70
Content-Length: 0

101957: .Nov 27 17:33:05.154: %VOIPAAA-5-VOIP_CALL_HISTORY: CallLegType 2, ConnectionId 55C5A9C737EF11E2B288D61E695CAF39, SetupTime .17:33:05.044 UTC Tue Nov 27 2012, PeerAddress 2055551234, PeerSubAddress , DisconnectCause 1B  , DisconnectText destination out of order (27), ConnectTime .17:33:05.154 UTC Tue Nov 27 2012, DisconnectTime .17:33:05.154 UTC Tue Nov 27 2012, CallOrigin 2, ChargedUnits 0, InfoType 2, TransmitPackets 0, TransmitBytes 0, ReceivePackets 0, ReceiveBytes 0
101958: .Nov 27 17:33:05.158: //-1/xxxxxxxxxxxx/CCAPI/cc_build_feature_vsa:
  101959: .Nov 27 17:33:05.158: :Inside cc_build_feature_vsa
101960: .Nov 27 17:33:05.158: //-1/xxxxxxxxxxxx/CCAPI/cc_build_feature_vsa:
  101961: .Nov 27 17:33:05.158:  feature call basic
101962: .Nov 27 17:33:05.158: //-1/xxxxxxxxxxxx/CCAPI/cc_build_feature_vsa:
  101963: .Nov 27 17:33:05.158: cc_build_feature_vsa attr is fn:TWC,ft:11/27/2012 17:33:05.042,cgn:2055551234,cdn:2054445678,frs:0,fid:46019,fcid:55C5A9C737EF11E2B288D61E695CAF39,legID:B4BE
101964: .Nov 27 17:33:05.158: %VOIPAAA-5-VOIP_FEAT_HISTORY: FEAT_VSA=fn:TWC,ft:11/27/2012 17:33:05.042,cgn:2055551234,cdn:2054445678,frs:0,fid:46019,fcid:55C5A9C737EF11E2B288D61E695CAF39,legID:B4BE,bguid:55C5A9C737EF11E2B288D61E695CAF39
101965: .Nov 27 17:33:05.158: //46270/55C5A9C7B288/CCAPI/cc_api_call_disconnect_done:
   Disposition=0, Interface=0x471F0134, Tag=0x0, Call Id=46270,
   Call Entry(Disconnect Cause=27, Voice Class Cause Code=0, Retry Count=0)
101966: .Nov 27 17:33:05.158: //46270/55C5A9C7B288/CCAPI/cc_api_call_disconnect_done:
   Call Disconnect Event Sent
101967: .Nov 27 17:33:05.158: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
  101968: .Nov 27 17:33:05.158: :cc_free_feature_vsa freeing 46A53578
101969: .Nov 27 17:33:05.158: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
  101970: .Nov 27 17:33:05.158:  vsacount in free is 4
101971: .Nov 27 17:33:05.234: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
INVITE sip:2054445678@10.10.10.10:5060 SIP/2.0
Via: SIP/2.0/UDP 4.4.4.4:5060;branch=z9hG4bK04Bd7b9194d9fd0ad8e
From: "KILLEN,SHANE" <sip:2055551234@4.4.4.4;pstn-params=9084818088;cpc=ordinary>;tag=gK04172686
To: <sip:2054445678@10.10.10.10>
Call-ID: 263340_8103886@4.4.4.4
CSeq: 1991 INVITE
Max-Forwards: 66
Allow: INVITE,ACK,CANCEL,BYE,REGISTER,REFER,INFO,SUBSCRIBE,NOTIFY,PRACK,UPDATE,OPTIONS
Accept: application/sdp, application/isup, application/dtmf, application/dtmf-relay,  multipart/mixed
Contact: "KILLEN,SHANE" <sip:2055551234@4.4.4.4:5060>
Remote-Party-ID: "KILLEN,SHANE" <sip:2055551234@4.4.4.4:5060>;privacy=off
Supported: timer
Session-Expires: 1800
Min-SE: 90
Content-Length:  306
Content-Disposition: session; handling=required
Content-Type: application/sdp

v=0
o=Sonus_UAC 16277 17782 IN IP4 4.4.4.4
s=SIP Media Capabilities
c=IN IP4 64.158.162.80
t=0 0
m=audio 25842 RTP/AVP 0 18 8 101
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv
a=ptime:20

101972: .Nov 27 17:33:05.246: //46272/xxxxxxxxxxxx/CCAPI/cc_api_caps_ind:
   Call Entry Is Not Found
101973: .Nov 27 17:33:05.250: //-1/55E602D1B28D/CCAPI/cc_api_display_ie_subfields:
   cc_api_call_setup_ind_common:
   cisco-username=2055551234
   ----- ccCallInfo IE subfields -----
   cisco-ani=sip:2055551234@4.4.4.4;pstn-params=9084818088;cpc=ordinary
   cisco-anitype=0
   cisco-aniplan=0
   cisco-anipi=0
   cisco-anisi=0
   dest=sip:2054445678@10.10.10.10:5060
   cisco-desttype=0
   cisco-destplan=0
   cisco-rdie=FFFFFFFF
   cisco-rdn=
   cisco-rdntype=0
   cisco-rdnplan=0
   cisco-rdnpi=-1
   cisco-rdnsi=-1
   cisco-redirectreason=-1   fwd_final_type =0
   final_redirectNumber =
   hunt_group_timeout =0

101974: .Nov 27 17:33:05.250: //-1/55E602D1B28D/CCAPI/cc_api_call_setup_ind_common:
   Interface=0x471F0134, Call Info(
   Calling Number=sip:2055551234@4.4.4.4;pstn-params=9084818088;cpc=ordinary,(Calling Name=)(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed),
   Called Number=sip:2054445678@10.10.10.10:5060(TON=Unknown, NPI=Unknown),
   Calling Translated=FALSE, Subscriber Type Str=Unknown, FinalDestinationFlag=TRUE,
   Incoming Dial-peer=16, Progress Indication=NULL(0), Calling IE Present=TRUE,
   Source Trkgrp Route Label=, Target Trkgrp Route Label=, CLID Transparent=FALSE), Call Id=46272
101975: .Nov 27 17:33:05.250: //-1/55E602D1B28D/CCAPI/ccCheckClipClir:
   In: Calling Number=sip:2055551234@4.4.4.4;pstn-params=9084818088;cpc=ordinary(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
101976: .Nov 27 17:33:05.250: //-1/55E602D1B28D/CCAPI/ccCheckClipClir:
   Out: Calling Number=sip:2055551234@4.4.4.4;pstn-params=9084818088;cpc=ordinary(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
101977: .Nov 27 17:33:05.250: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
  101978: .Nov 27 17:33:05.250: :cc_get_feature_vsa malloc success
101979: .Nov 27 17:33:05.254: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
  101980: .Nov 27 17:33:05.254:  cc_get_feature_vsa count is 5
101981: .Nov 27 17:33:05.254: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
  101982: .Nov 27 17:33:05.254: :FEATURE_VSA attributes are: feature_name:0,feature_time:1185232256,feature_id:46021
101983: .Nov 27 17:33:05.254: //46272/55E602D1B28D/CCAPI/cc_api_call_setup_ind_common:
   Set Up Event Sent;
   Call Info(Calling Number=(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed),
   Called Number=(TON=Unknown, NPI=Unknown))
101984: .Nov 27 17:33:05.258: //46272/55E602D1B28D/CCAPI/cc_process_call_setup_ind:
   Event=0x4735E310
101985: .Nov 27 17:33:05.258: //46272/55E602D1B28D/CCAPI/ccCallSetContext:
   Context=0x45C3D44C
101986: .Nov 27 17:33:05.258: //46272/55E602D1B28D/CCAPI/cc_process_call_setup_ind:
   >>>>CCAPI handed cid 46272 with tag 16 to app "_ManagedAppProcess_Default"
101987: .Nov 27 17:33:05.262: //46272/55E602D1B28D/CCAPI/ccCallProceeding:
   Progress Indication=NULL(0)
101988: .Nov 27 17:33:05.262: //-1/xxxxxxxxxxxx/CCAPI/ccGetMemPoolFromContainer:
   mempool not found from usrContainer(47BBE100)
101989: .Nov 27 17:33:05.262: //-1/xxxxxxxxxxxx/CCAPI/ccCreateMemPoolInContainer:
   Mempool(47DD4E08) created in usrContainer(47BBE100)
101990: .Nov 27 17:33:05.266: //46272/55E602D1B28D/CCAPI/ccCallSetupRequest:
   Destination=, Calling IE Present=TRUE, Mode=0,
   Outgoing Dial-peer=111, Params=0x47D06F18, Progress Indication=NULL(0)
101991: .Nov 27 17:33:05.266: //46272/55E602D1B28D/CCAPI/ccCheckClipClir:
   In: Calling Number=sip:2055551234@4.4.4.4;pstn-params=9084818088;cpc=ordinary(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
101992: .Nov 27 17:33:05.266: //46272/55E602D1B28D/CCAPI/ccCheckClipClir:
   Out: Calling Number=sip:2055551234@4.4.4.4;pstn-params=9084818088;cpc=ordinary(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
101993: .Nov 27 17:33:05.266: //46272/55E602D1B28D/CCAPI/ccCallSetupRequest:
   Destination Pattern=20571669.., Called Number=2054445678, Digit Strip=FALSE
101994: .Nov 27 17:33:05.266: //46272/55E602D1B28D/CCAPI/ccCallSetupRequest:
   Calling Number=sip:2055551234@4.4.4.4;pstn-params=9084818088;cpc=ordinary(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed),
   Called Number=2054445678(TON=Unknown, NPI=Unknown),
   Redirect Number=, Display Info=KILLEN,SHANE
   Account Number=2055551234, Final Destination Flag=TRUE,
   Guid=55E602D1-37EF-11E2-B28D-D61E695CAF39, Outgoing Dial-peer=111
101995: .Nov 27 17:33:05.266: //46272/55E602D1B28D/CCAPI/cc_api_display_ie_subfields:
   ccCallSetupRequest:
   cisco-username=2055551234
   ----- ccCallInfo IE subfields -----
   cisco-ani=sip:2055551234@4.4.4.4;pstn-params=9084818088;cpc=ordinary
   cisco-anitype=0
   cisco-aniplan=0
   cisco-anipi=0
   cisco-anisi=0
   dest=2054445678
   cisco-desttype=0
   cisco-destplan=0
   cisco-rdie=FFFFFFFF
   cisco-rdn=
   cisco-rdntype=0
   cisco-rdnplan=0
   cisco-rdnpi=-1
   cisco-rdnsi=-1
   cisco-redirectreason=-1   fwd_final_type =0
   final_redirectNumber =
   hunt_group_timeout =0

101996: .Nov 27 17:33:05.270: //46272/55E602D1B28D/CCAPI/ccIFCallSetupRequestPrivate:
   Interface=0x46F4AAA8, Interface Type=1, Destination=, Mode=0x0,
   Call Params(Calling Number=sip:2055551234@4.4.4.4;pstn-params=9084818088;cpc=ordinary,(Calling Name=KILLEN,SHANE)(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed),
   Called Number=2054445678(TON=Unknown, NPI=Unknown), Calling Translated=FALSE,
   Subscriber Type Str=Unknown, FinalDestinationFlag=TRUE, Outgoing Dial-peer=111, Call Count On=FALSE,
   Source Trkgrp Route Label=, Target Trkgrp Route Label=, tg_label_flag=0, Application Call Id=)
101997: .Nov 27 17:33:05.270: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
  101998: .Nov 27 17:33:05.270: :cc_get_feature_vsa malloc success
101999: .Nov 27 17:33:05.270: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
  102000: .Nov 27 17:33:05.270:  cc_get_feature_vsa count is 6
102001: .Nov 27 17:33:05.270: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
  102002: .Nov 27 17:33:05.270: :FEATURE_VSA attributes are: feature_name:0,feature_time:1185229664,feature_id:46022
102003: .Nov 27 17:33:05.270: //46273/55E602D1B28D/CCAPI/ccIFCallSetupRequestPrivate:
   SPI Call Setup Request Is Success; Interface Type=1, FlowMode=1
102004: .Nov 27 17:33:05.270: //46273/55E602D1B28D/CCAPI/ccCallSetContext:
   Context=0x47D06EC8
102005: .Nov 27 17:33:05.270: //46272/55E602D1B28D/CCAPI/ccSaveDialpeerTag:
   Outgoing Dial-peer=111
102006: .Nov 27 17:33:05.298: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 4.4.4.4:5060;branch=z9hG4bK04Bd7b9194d9fd0ad8e
From: "KILLEN,SHANE" <sip:2055551234@4.4.4.4;pstn-params=9084818088;cpc=ordinary>;tag=gK04172686
To: <sip:2054445678@10.10.10.10>
Date: Tue, 27 Nov 2012 17:33:05 GMT
Call-ID: 263340_8103886@4.4.4.4
CSeq: 1991 INVITE
Allow-Events: telephone-event
Server: Cisco-SIPGateway/IOS-12.x
Content-Length: 0

102007: .Nov 27 17:33:05.302: //46273/55E602D1B28D/CCAPI/cc_api_set_called_ccm_detected:
   CallInfo(called ccm detected=TRUE ccmVersion 3)
102008: .Nov 27 17:33:05.302: //46273/55E602D1B28D/CCAPI/cc_api_call_proceeding:
   Interface=0x46F4AAA8, Progress Indication=NULL(0)
102009: .Nov 27 17:33:05.302: //46273/55E602D1B28D/CCAPI/cc_api_call_disconnected:
   Cause Value=27, Interface=0x46F4AAA8, Call Id=46273
102010: .Nov 27 17:33:05.302: //46273/55E602D1B28D/CCAPI/cc_api_call_disconnected:
   Call Entry(Responsed=TRUE, Cause Value=27, Retry Count=0)
102011: .Nov 27 17:33:05.306: //46272/xxxxxxxxxxxx/CCAPI/ccCallReleaseResources:
   release reserved xcoding resource.
102012: .Nov 27 17:33:05.306: //46273/55E602D1B28D/CCAPI/ccCallSetAAA_Accounting:
   Accounting=0, Call Id=46273
102013: .Nov 27 17:33:05.310: //46273/55E602D1B28D/CCAPI/ccCallDisconnect:
   Cause Value=27, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=27)
102014: .Nov 27 17:33:05.310: //46273/55E602D1B28D/CCAPI/ccCallDisconnect:
   Cause Value=27, Call Entry(Responsed=TRUE, Cause Value=27)
102015: .Nov 27 17:33:05.310: //46273/55E602D1B28D/CCAPI/cc_api_get_transfer_info:
   Transfer Number Is Null
102016: .Nov 27 17:33:05.310: %VOIPAAA-5-VOIP_CALL_HISTORY: CallLegType 2, ConnectionId 55E602D137EF11E2B28DD61E695CAF39, SetupTime .17:33:05.280 UTC Tue Nov 27 2012, PeerAddress 2054445678, PeerSubAddress , DisconnectCause 1B  , DisconnectText destination out of order (27), ConnectTime .17:33:05.310 UTC Tue Nov 27 2012, DisconnectTime .17:33:05.310 UTC Tue Nov 27 2012, CallOrigin 1, ChargedUnits 0, InfoType 2, TransmitPackets 0, TransmitBytes 0, ReceivePackets 0, ReceiveBytes 0
102017: .Nov 27 17:33:05.314: //-1/xxxxxxxxxxxx/CCAPI/cc_build_feature_vsa:
  102018: .Nov 27 17:33:05.314: :Inside cc_build_feature_vsa
102019: .Nov 27 17:33:05.314: //-1/xxxxxxxxxxxx/CCAPI/cc_build_feature_vsa:
  102020: .Nov 27 17:33:05.314:  feature call basic
102021: .Nov 27 17:33:05.314: //-1/xxxxxxxxxxxx/CCAPI/cc_build_feature_vsa:
  102022: .Nov 27 17:33:05.314: cc_build_feature_vsa attr is fn:TWC,ft:11/27/2012 17:33:05.270,cgn:2055551234,cdn:2054445678,frs:0,fid:46022,fcid:55E602D137EF11E2B28DD61E695CAF39,legID:B4C1
102023: .Nov 27 17:33:05.314: %VOIPAAA-5-VOIP_FEAT_HISTORY: FEAT_VSA=fn:TWC,ft:11/27/2012 17:33:05.270,cgn:2055551234,cdn:2054445678,frs:0,fid:46022,fcid:55E602D137EF11E2B28DD61E695CAF39,legID:B4C1,bguid:55E602D137EF11E2B28DD61E695CAF39
102024: .Nov 27 17:33:05.314: //46273/55E602D1B28D/CCAPI/cc_api_call_disconnect_done:
   Disposition=0, Interface=0x46F4AAA8, Tag=0x0, Call Id=46273,
   Call Entry(Disconnect Cause=27, Voice Class Cause Code=0, Retry Count=0)
102025: .Nov 27 17:33:05.318: //46273/55E602D1B28D/CCAPI/cc_api_call_disconnect_done:
   Call Disconnect Event Sent
102026: .Nov 27 17:33:05.318: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
  102027: .Nov 27 17:33:05.318: :cc_free_feature_vsa freeing 46A52B58
102028: .Nov 27 17:33:05.318: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
 102029: .Nov 27 17:33:05.318:  vsacount in free is 5
102030: .Nov 27 17:33:05.322: //-1/xxxxxxxxxxxx/CCAPI/ccMemPoolTDFreeHelper:
   data = 47BCC080
102031: .Nov 27 17:33:05.322: ccMemPoolTDFreeHelper:mem_mgr_mempool_free: mem_refcnt(47DD4E08)=0 - mempool cleanup
102032: .Nov 27 17:33:05.322: //46272/55E602D1B28D/CCAPI/ccCallDisconnect:
   Cause Value=27, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=0)
102033: .Nov 27 17:33:05.322: //46272/55E602D1B28D/CCAPI/ccCallDisconnect:
   Cause Value=27, Call Entry(Responsed=TRUE, Cause Value=27)
102034: .Nov 27 17:33:05.326: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 404 Not Found
Via: SIP/2.0/UDP 4.4.4.4:5060;branch=z9hG4bK04Bd7b9194d9fd0ad8e
From: "KILLEN,SHANE" <sip:2055551234@4.4.4.4;pstn-params=9084818088;cpc=ordinary>;tag=gK04172686
To: <sip:2054445678@10.10.10.10>;tag=ECFD0680-22B6
Date: Tue, 27 Nov 2012 17:33:05 GMT
Call-ID: 263340_8103886@4.4.4.4
CSeq: 1991 INVITE
Allow-Events: telephone-event
Server: Cisco-SIPGateway/IOS-12.x
Reason: Q.850;cause=27
Content-Length: 0

102035: .Nov 27 17:33:05.710: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
ACK sip:2054445678@10.10.10.10:5060 SIP/2.0
Via: SIP/2.0/UDP 4.4.4.4:5060;branch=z9hG4bK04Bd7b9194d9fd0ad8e
From: "KILLEN,SHANE" <sip:2055551234@4.4.4.4;pstn-params=9084818088;cpc=ordinary>;tag=gK04172686
To: <sip:2054445678@10.10.10.10>;tag=ECFD0680-22B6
Call-ID: 263340_8103886@4.4.4.4
CSeq: 1991 ACK
Max-Forwards: 70
Content-Length: 0