Cisco Support Community
cancel
Showing results for 
Search instead for 
Did you mean: 
Announcements

Welcome to Cisco Support Community. We would love to have your feedback.

For an introduction to the new site, click here. And see here for current known issues.

New Member

Forwarding DDI PSTN call from UC500 to CUCM via SIP trunk shows "Busy"

Hi all,

We have a UC500 with two BRI connections, and a SIP trunk to a CUCM 8.6 cluster.

The SIP trunk works fine, we can dial from phones attached to the UC500 to phones connected to the CUCM and vice versa but at the minute, one of the incoming DDI numbers (5310) is translating to a phone on the UC500, but we instead want to send this call across the SIP trunk and to a phone connected to the CUCM (1001).

I have tried this by changing the number on the incoming translation to be the CUCM phone, and by CFA the UC500 phone to the CUCM phone, but both ways, the call fails and I get a disconnect cause of 17:

DEBUG CCAPI

001728: Aug 28 13:56:22.698: ISDN BR0/1/0 Q931: RX <- SETUP pd = 8  callref = 0x15

        Sending Complete

        Bearer Capability i = 0x9090A3

                Standard = CCITT

                Transfer Capability = 3.1kHz Audio

                Transfer Mode = Circuit

                Transfer Rate = 64 kbit/s

        Channel ID i = 0x89

                Exclusive, B1

        Progress Ind i = 0x8581 - Call not end-to-end ISDN, may have in-band info  

                Plan:ISDN, Type:National

        Called Party Number i = 0x81, '5310'

                Plan:ISDN, Type:Unknown

001729: Aug 28 13:56:22.706: //-1/74F7EF37800A/CCAPI/cc_api_display_ie_subfields:

   cc_api_call_setup_ind_common:

   cisco-username=

   ----- ccCallInfo IE subfields -----

   cisco-ani=

   cisco-anitype=2

   cisco-aniplan=1

   cisco-anipi=0

   cisco-anisi=3

   dest=5310

   cisco-desttype=0

   cisco-destplan=1

   cisco-rdie=FFFFFFFF

   cisco-rdn=

   cisco-rdntype=-1

   cisco-rdnplan=-1

   cisco-rdnpi=-1

   cisco-rdnsi=-1

   cisco-redirectreason=-1   fwd_final_type =0

   final_redirectNumber =

   hunt_group_timeout =0

001730: Aug 28 13:56:22.706: //-1/74F7EF37800A/CCAPI/cc_api_call_setup_ind_common:

   Interface=0x8871F110, Call Info(

   Calling Number=,(Calling Name=)(TON=National, NPI=ISDN, Screening=Network, Presentation=Allowed),

   Called Number=5310(TON=Unknown, NPI=ISDN),

   Calling Translated=FALSE, Subscriber Type Str=RegularLine, FinalDestinationFlag=TRUE,

   Incoming Dial-peer=3003, Progress Indication=NOT END TO END ISDN(1), Calling IE Present=TRUE,

   Source Trkgrp Route Label=ALL_BRI, Target Trkgrp Route Label=, CLID Transparent=FALSE), Call Id=-1

001731: Aug 28 13:56:22.706: //-1/74F7EF37800A/CCAPI/ccCheckClipClir:

   In: Calling Number=(TON=National, NPI=ISDN, Screening=Network, Presentation=Allowed)

001732: Aug 28 13:56:22.706: //-1/74F7EF37800A/CCAPI/ccCheckClipClir:

   Out: Calling Number=(TON=National, NPI=ISDN, Screening=Network, Presentation=Allowed)

001733: Aug 28 13:56:22.706: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

001734: Aug 28 13:56:22.706: :cc_get_feature_vsa malloc success

001735: Aug 28 13:56:22.706: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

001736: Aug 28 13:56:22.706:  cc_get_feature_vsa count is 3

001737: Aug 28 13:56:22.706: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

001738: Aug 28 13:56:22.706: :FEATURE_VSA attributes are: feature_name:0,feature_time:2254826760,feature_id:161

001739: Aug 28 13:56:22.706: //95/74F7EF37800A/CCAPI/cc_api_call_setup_ind_common:

   Set Up Event Sent;

   Call Info(Calling Number=(TON=National, NPI=ISDN, Screening=Network, Presentation=Allowed),

   Called Number=5310(TON=Unknown, NPI=ISDN))

001740: Aug 28 13:56:22.710: //95/74F7EF37800A/CCAPI/cc_process_call_setup_ind:

   Event=0x886AF2F8

001741: Aug 28 13:56:22.710: //-1/xxxxxxxxxxxx/CCAPI/cc_setupind_match_search:

   Try with the demoted called number 5310

001742: Aug 28 13:56:22.710: //95/74F7EF37800A/CCAPI/ccCallSetContext:

   Context=0x8666922C

001743: Aug 28 13:56:22.710: //95/74F7EF37800A/CCAPI/cc_process_call_setup_ind:

   >>>>CCAPI handed cid 95 with tag 3003 to app "_ManagedAppProcess_Default"

001744: Aug 28 13:56:22.714: //95/74F7EF37800A/CCAPI/ccCallProceeding:

   Progress Indication=NULL(0)

001745: Aug 28 13:56:22.718: //95/74F7EF37800A/CCAPI/ccCallSetupRequest:

   Destination=, Calling IE Present=TRUE, Mode=0,

   Outgoing Dial-peer=400001, Params=0x8666A73C, Progress Indication=NOT END TO END ISDN(1)

001746: Aug 28 13:56:22.718: //95/74F7EF37800A/CCAPI/ccCheckClipClir:

   In: Calling Number=(TON=National, NPI=ISDN, Screening=Network, Presentation=Allowed)

001747: Aug 28 13:56:22.718: //95/74F7EF37800A/CCAPI/ccCheckClipClir:

   Out: Calling Number=(TON=National, NPI=ISDN, Screening=Network, Presentation=Allowed)

001748: Aug 28 13:56:22.718: //95/74F7EF37800A/CCAPI/ccCallSetupRequest:

   Destination Pattern=1001, Called Number=1001, Digit Strip=FALSE

001749: Aug 28 13:56:22.718: //95/74F7EF37800A/CCAPI/ccCallSetupRequest:

   Calling Number=(TON=National, NPI=ISDN, Screening=Network, Presentation=Allowed),

   Called Number=1001(TON=Unknown, NPI=ISDN),

   Redirect Number=, Display Info=

   Account Number=, Final Destination Flag=TRUE,

   Guid=74F7EF37-0F20-11E3-800A-001E7A428180, Outgoing Dial-peer=400001

001750: Aug 28 13:56:22.718: //95/74F7EF37800A/CCAPI/cc_api_display_ie_subfields:

   ccCallSetupRequest:

   cisco-username=

   ----- ccCallInfo IE subfields -----

   cisco-ani=90

   cisco-anitype=2

   cisco-aniplan=1

   cisco-anipi=0

   cisco-anisi=3

   dest=1001

   cisco-desttype=0

   cisco-destplan=1

   cisco-rdie=FFFFFFFF

   cisco-rdn=

   cisco-rdntype=-1

   cisco-rdnplan=-1

   cisco-rdnpi=-1

   cisco-rdnsi=-1

   cisco-redirectreason=-1   fwd_final_type =0

   final_redirectNumber =

   hunt_group_timeout =0

001751: Aug 28 13:56:22.718: //95/74F7EF37800A/CCAPI/ccIFCallSetupRequestPrivate:

   Interface=0x87529DBC, Interface Type=3, Destination=, Mode=0x0,

   Call Params(Calling Number=,(Calling Name=)(TON=National, NPI=ISDN, Screening=Network, Presentation=Allowed),

   Called Number=1001(TON=Unknown, NPI=ISDN), Calling Translated=FALSE,

   Subscriber Type Str=RegularLine, FinalDestinationFlag=TRUE, Outgoing Dial-peer=400001, Call Count On=FALSE,

   Source Trkgrp Route Label=ALL_BRI, Target Trkgrp Route Label=, tg_label_flag=1, Application Call Id=)

001752: Aug 28 13:56:22.718: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

001753: Aug 28 13:56:22.718: :cc_get_feature_vsa malloc success

001754: Aug 28 13:56:22.718: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

001755: Aug 28 13:56:22.718:  cc_get_feature_vsa count is 4

001756: Aug 28 13:56:22.718: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

001757: Aug 28 13:56:22.718: :FEATURE_VSA attributes are: feature_name:0,feature_time:2254826984,feature_id:162

001758: Aug 28 13:56:22.718: //96/74F7EF37800A/CCAPI/ccIFCallSetupRequestPrivate:

   SPI Call Setup Request Is Success; Interface Type=3, FlowMode=1

001759: Aug 28 13:56:22.718: //96/74F7EF37800A/CCAPI/ccCallSetContext:

   Context=0x8666A6EC

001760: Aug 28 13:56:22.718: //95/74F7EF37800A/CCAPI/ccSaveDialpeerTag:

   Outgoing Dial-peer=400001

001761: Aug 28 13:56:22.722: //96/74F7EF37800A/CCAPI/cc_api_call_proceeding:

   Interface=0x87529DBC, Progress Indication=NULL(0)

001762: Aug 28 13:56:22.750: ISDN BR0/1/0 Q931: TX -> CALL_PROC pd = 8  callref = 0x95

        Channel ID i = 0x89

                Exclusive, B1

001763: Aug 28 13:56:22.814: //96/74F7EF37800A/CCAPI/cc_api_call_disconnected:

   Cause Value=17, Interface=0x87529DBC, Call Id=96

001764: Aug 28 13:56:22.814: //96/74F7EF37800A/CCAPI/cc_api_call_disconnected:

   Call Entry(Responsed=TRUE, Cause Value=17, Retry Count=0)

001765: Aug 28 13:56:22.814: //95/74F7EF37800A/CCAPI/ccCallReleaseResources:

   release reserved xcoding resource.

001766: Aug 28 13:56:22.814: //96/74F7EF37800A/CCAPI/ccCallSetAAA_Accounting:

   Accounting=0, Call Id=96

001767: Aug 28 13:56:22.814: //96/74F7EF37800A/CCAPI/ccCallDisconnect:

   Cause Value=17, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=17)

001768: Aug 28 13:56:22.814: //96/74F7EF37800A/CCAPI/ccCallDisconnect:

   Cause Value=17, Call Entry(Responsed=TRUE, Cause Value=17)

001769: Aug 28 13:56:22.814: //96/74F7EF37800A/CCAPI/cc_api_call_disconnect_done:

   Disposition=0, Interface=0x87529DBC, Tag=0x0, Call Id=96,

   Call Entry(Disconnect Cause=17, Voice Class Cause Code=0, Retry Count=0)

001770: Aug 28 13:56:22.814: //96/74F7EF37800A/CCAPI/cc_api_call_disconnect_done:

   Call Disconnect Event Sent

001771: Aug 28 13:56:22.818: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

001772: Aug 28 13:56:22.818: :cc_free_feature_vsa freeing 8665EDE0

001773: Aug 28 13:56:22.818: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

001774: Aug 28 13:56:22.818:  vsacount in free is 3

001775: Aug 28 13:56:22.822: //95/74F7EF37800A/CCAPI/ccCallDisconnect:

   Cause Value=17, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=0)

001776: Aug 28 13:56:22.822: //95/74F7EF37800A/CCAPI/ccCallDisconnect:

   Cause Value=17, Call Entry(Responsed=TRUE, Cause Value=17)

001777: Aug 28 13:56:22.822: //95/74F7EF37800A/CCAPI/cc_api_get_transfer_info:

   Transfer Number Is Null

001778: Aug 28 13:56:22.826: ISDN BR0/1/0 Q931: TX -> DISCONNECT pd = 8  callref = 0x95

        Cause i = 0x8091 - User busy

001779: Aug 28 13:56:22.886: ISDN BR0/1/0 Q931: RX <- RELEASE pd = 8  callref = 0x15

001780: Aug 28 13:56:22.890: ISDN BR0/1/0 Q931: TX -> RELEASE_COMP pd = 8  callref = 0x95

001781: Aug 28 13:56:22.894: //95/74F7EF37800A/CCAPI/cc_api_call_disconnect_done:

   Disposition=0, Interface=0x8871F110, Tag=0x0, Call Id=95,

   Call Entry(Disconnect Cause=17, Voice Class Cause Code=0, Retry Count=0)

001782: Aug 28 13:56:22.894: //95/74F7EF37800A/CCAPI/cc_api_call_disconnect_done:

   Call Disconnect Event Sent

001783: Aug 28 13:56:22.898: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

001784: Aug 28 13:56:22.898: :cc_free_feature_vsa freeing 8665ED00

001785: Aug 28 13:56:22.898: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

001786: Aug 28 13:56:22.898:  vsacount in free is 2

DEBUG CCSIP

002051: Aug 28 14:05:07.378: //-1/xxxxxxxxxxxx/SIP/Info/httpish_msg_process_network_msg: MSG LINE READ FAILURE DUE TO RS->EOF

002052: Aug 28 14:05:07.378: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_network_message: process_network_msg: not complete

002053: Aug 28 14:05:07.378: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:

Received:

002054: Aug 28 14:05:07.378: //-1/xxxxxxxxxxxx/SIP/Error/HandleUdpIPv4SocketReads: SIP Message incomplete, trashed

002055: Aug 28 14:05:23.587: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAddContextToTable: Added context(0x88B4C2A0) with key=[97] to table

002056: Aug 28 14:05:23.587: //-1/000000000000/SIP/Info/ccsip_offer_ans_init:

002057: Aug 28 14:05:23.587: //-1/000000000000/SIP/Info/ccsip_iwf_init: 

002058: Aug 28 14:05:23.587: //-1/000000000000/SIP/Info/ccsip_ipip_media_service_init:

002059: Aug 28 14:05:23.587: //-1/000000000000/SIP/Info/sipSPI_ipip_vcc_Initialization:  Entry...

002060: Aug 28 14:05:23.587: //104/000000000000/SIP/State/sipSPIChangeState: 0x88B4C2A0 : State change from (STATE_NONE, SUBSTATE_NONE)  to (STATE_IDLE, SUBSTATE_NONE)

002061: Aug 28 14:05:23.587: //104/000000000000/SIP/Info/ccsip_call_setup_request: Set Protocol information

002062: Aug 28 14:05:23.587: //104/000000000000/SIP/Info/ccsip_iwf_handle_peer_event:

002063: Aug 28 14:05:23.587: //104/000000000000/SIP/Info/ccsip_iwf_map_ccapi_event_to_iwf_event: Event Category: 1, Event Id: 176

002064: Aug 28 14:05:23.587: //104/000000000000/SIP/Info/ccsip_iwf_process_event: 

002065: Aug 28 14:05:23.587: //104/000000000000/SIP/State/ccsip_cnfsm_debugs: IWF:cur_container:sip_iwf_default_early_dialog_container, cur_state:S_SIP_IWF_SDP_IDLE, event:E_SIP_IWF_EV_SET_MODE

002066: Aug 28 14:05:23.587: //104/000000000000/SIP/State/ccsip_cnfsm_debugs: IWF:new_container:sip_iwf_main_container

002067: Aug 28 14:05:23.587: //104/000000000000/SIP/Info/ccsip_get_int_type_frm_set_mode_ev:

002068: Aug 28 14:05:23.587: //104/000000000000/SIP/Info/is_mode_sip_sip_md:

002069: Aug 28 14:05:23.587: //104/000000000000/SIP/Info/ccsip_get_int_type_frm_set_mode_ev:

002070: Aug 28 14:05:23.587: //104/000000000000/SIP/Info/is_mode_sip_sip_ed:

002071: Aug 28 14:05:23.587: //104/000000000000/SIP/Info/ccsip_get_int_type_frm_set_mode_ev:

002072: Aug 28 14:05:23.587: //104/000000000000/SIP/Info/is_mode_sip_h32x_in_set_mode:

002073: Aug 28 14:05:23.587: //104/000000000000/SIP/Info/ccsip_get_int_type_frm_set_mode_ev:

002074: Aug 28 14:05:23.587: //104/000000000000/SIP/Info/is_mode_sip_h323_in_set_mode:

002075: Aug 28 14:05:23.587: //104/000000000000/SIP/Info/ccsip_get_int_type_frm_set_mode_ev:

002076: Aug 28 14:05:23.587: //104/000000000000/SIP/Info/is_mode_sip_sccp_in_set_mode:

002077: Aug 28 14:05:23.587: //104/000000000000/SIP/Info/ccsip_get_int_type_frm_set_mode_ev:

002078: Aug 28 14:05:23.587: //104/000000000000/SIP/Info/is_mode_sip_sccp_in_set_mode:

002079: Aug 28 14:05:23.587: //104/000000000000/SIP/Info/sip_iwf_def_set_mode_hdlr: Setting SPI mode to SIP-TDM

002080: Aug 28 14:05:23.587: //104/000000000000/SIP/State/ccsip_cnfsm_debugs: IWF:new_container:sip_iwf_default_early_dialog_container

002081: Aug 28 14:05:23.587: //104/000000000000/SIP/State/ccsip_cnfsm_debugs: IWF:next_state:CNFSM_NO_STATE_CHANGE

002082: Aug 28 14:05:23.587: //104/000000000000/SIP/Info/ccsip_iwf_handle_peer_event: Return value : SIP_IWF_SUCCESS

002083: Aug 28 14:05:23.587: //104/000000000000/SIP/Info/ccsip_iwf_handle_peer_event:

002084: Aug 28 14:05:23.587: //104/000000000000/SIP/Info/ccsip_iwf_map_ccapi_event_to_iwf_event: Event Category: 3, Event Id: 5

002085: Aug 28 14:05:23.591: //104/000000000000/SIP/Info/ccsip_iwf_process_event: 

002086: Aug 28 14:05:23.591: //104/000000000000/SIP/State/ccsip_cnfsm_debugs: IWF:cur_container:sip_iwf_default_early_dialog_container, cur_state:S_SIP_IWF_SDP_IDLE, event:E_SIP_IWF_EV_SET_FLOW_MODE

002087: Aug 28 14:05:23.591: //104/000000000000/SIP/State/ccsip_cnfsm_debugs: IWF:new_container:sip_iwf_main_container

002088: Aug 28 14:05:23.591: //104/000000000000/SIP/Info/is_fa2ft_md_flow_mode_transition:

002089: Aug 28 14:05:23.591: //104/000000000000/SIP/Info/is_fa2ft_flow_mode_transition:

002090: Aug 28 14:05:23.591: //104/000000000000/SIP/Info/ccsip_get_flow_mode_frm_set_flow_mode_ev:

002091: Aug 28 14:05:23.591: //104/000000000000/SIP/Info/is_fa2ft_flow_mode_transition:

002092: Aug 28 14:05:23.591: //104/000000000000/SIP/Info/ccsip_get_flow_mode_frm_set_flow_mode_ev:

002093: Aug 28 14:05:23.591: //104/000000000000/SIP/Info/ccsip_iwf_process_event: IWF - cnfsm ret 2

002094: Aug 28 14:05:23.591: //104/000000000000/SIP/Info/ccsip_iwf_handle_peer_event: Return value : SIP_IWF_SUCCESS

002095: Aug 28 14:05:23.591: //104/000000000000/SIP/Info/ccsip_call_setup_request: Before processing SETUP REQccb->pld.flags_ipip = 200

002096: Aug 28 14:05:23.591: //104/000000000000/SIP/Info/ccsip_call_setup_request: After processing SETUP REQccb->pld.flags_ipip = 200

002097: Aug 28 14:05:23.591: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetOutboundHostAndDestHostPrivate: CCSIP: target_host : 192.168.11.250 target_port : 5060

002098: Aug 28 14:05:23.591: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_SETUP

002099: Aug 28 14:05:23.591: //104/B75A96E7800D/SIP/Info/ccsip_call_setup_request: Incrementing call counter to [1] in dial-peer [400001]

002100: Aug 28 14:05:23.591: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 2

002101: Aug 28 14:05:23.591: //104/B75A96E7800D/SIP/Info/sipSPIUaddccCallIdToTable: Adding call id 68 to table

002102: Aug 28 14:05:23.591: //104/B75A96E7800D/SIP/Info/sipSPIGetCallConfig: preferred_codec set[0] type :No Codec    bytes: 0

002103: Aug 28 14:05:23.591: //104/B75A96E7800D/SIP/Info/sipSPIGetCallConfig: Media forking disabled

002104: Aug 28 14:05:23.591: //104/B75A96E7800D/SIP/Info/sipSPIGetCallConfig: Media Antitrombone disabled

002105: Aug 28 14:05:23.591: //104/B75A96E7800D/SIP/Info/sipSPICanSetFallbackFlag: Local Fallback is not active

002106: Aug 28 14:05:23.591: //104/B75A96E7800D/SIP/Info/sipSPISetMediaFlowMode: Storing the configured mode as FLOW-THROUGH

002107: Aug 28 14:05:23.591: //104/B75A96E7800D/SIP/Info/sipSPISetMediaFlowMode: xcoder high-density disabled

002108: Aug 28 14:05:23.591: //104/B75A96E7800D/SIP/Info/sipSPISetMediaFlowMode: Flow Mode set to FLOW_THROUGH

002109: Aug 28 14:05:23.591: //104/B75A96E7800D/SIP/Info/sipSPIGetCallConfig: Checking Video Type Rate=-1 video_codec_allowed=1F

002110: Aug 28 14:05:23.591: //104/B75A96E7800D/SIP/Media/sipSPICopyStunConfigFromPeerToCCB: Firewall traversal is not enabled

002111: Aug 28 14:05:23.591: //104/B75A96E7800D/SIP/Info/sipSPIGetModemInfoPerCall: peer_callID=103

002112: Aug 28 14:05:23.591: //104/B75A96E7800D/SIP/Info/sipSPIGetCallConfig: Media forking disabled

002113: Aug 28 14:05:23.591: //104/B75A96E7800D/SIP/Info/sipSPISetOverlapConfiguration: Overlap signaling: FALSE: Endpt: SIP Trunk

002114: Aug 28 14:05:23.591: //104/B75A96E7800D/SIP/Info/sipSPI_ipip_GetHdrPassthruCfg: Hdr passthrough config:1 tag:0

002115: Aug 28 14:05:23.591: //104/B75A96E7800D/SIP/Info/sipSPI_ipip_GetCopyListCfg: Copy-list config:2 tag:0

002116: Aug 28 14:05:23.591: //104/B75A96E7800D/SIP/Info/sipSPI_ipip_build_consolidated_header_list: Both passthru and copylist are disabled

002117: Aug 28 14:05:23.591: //104/B75A96E7800D/SIP/Info/sipSPIValidateAndCopyOutboundHost: CCSIP: copy target_host to outbound_host

002118: Aug 28 14:05:23.591: //104/B75A96E7800D/SIP/Info/preprocessSetup:

This is a not a SIGO Call -, could be DM call

002119: Aug 28 14:05:23.591: //104/B75A96E7800D/SIP/Info/ccsip_iwf_process_event: 

002120: Aug 28 14:05:23.591: //104/B75A96E7800D/SIP/State/ccsip_cnfsm_debugs: IWF:cur_container:sip_iwf_default_early_dialog_container, cur_state:S_SIP_IWF_SDP_IDLE, event:E_SIP_IWF_EV_INIT_CALL_SETUP

002121: Aug 28 14:05:23.591: //104/B75A96E7800D/SIP/State/ccsip_cnfsm_debugs: IWF:new_container:sip_iwf_main_container

002122: Aug 28 14:05:23.595: //104/B75A96E7800D/SIP/Info/ccsip_iwf_process_event: IWF - cnfsm ret 2

002123: Aug 28 14:05:23.595: //104/B75A96E7800D/SIP/Info/sipSPIValidateStreamAddrType: stream:1, Mode : 1

002124: Aug 28 14:05:23.595: //-1/xxxxxxxxxxxx/SIP/Info/resolve_media_ip_address_to_bind: calling reg_invoke_ip_first_hop()

002125: Aug 28 14:05:23.595: //-1/xxxxxxxxxxxx/SIP/Info/resolve_media_ip_address_to_bind: calling ip_best_local_address()

002126: Aug 28 14:05:23.595: //-1/xxxxxxxxxxxx/SIP/Info/resolve_media_ip_address_to_bind: return addr 192.168.10.1

002127: Aug 28 14:05:23.595: //104/B75A96E7800D/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 192.168.10.1

002128: Aug 28 14:05:23.595: //-1/xxxxxxxxxxxx/SIP/Info/resolve_sig_ip_address_to_bind: calling reg_invoke_ip_first_hop()

002129: Aug 28 14:05:23.595: //-1/xxxxxxxxxxxx/SIP/Info/resolve_sig_ip_address_to_bind: calling ip_best_local_address()

002130: Aug 28 14:05:23.595: //-1/xxxxxxxxxxxx/SIP/Info/resolve_sig_ip_address_to_bind: return addr 192.168.10.1

002131: Aug 28 14:05:23.595: //-1/xxxxxxxxxxxx/SIP/Media/sipSPIReserveRtpPort: reserved port 17978 for stream 1

002132: Aug 28 14:05:23.595: //-1/xxxxxxxxxxxx/SIP/Info/convert_codec_bytes_to_ptime: Values :Codec: g711ulaw codecbytes :160, ptime: 20

002133: Aug 28 14:05:23.595: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetMediaDirectionForStream: Setting Media direction SENDRECV for stream 1

002134: Aug 28 14:05:23.595: //104/B75A96E7800D/SIP/Info/sip_generate_sdp_xcaps_list: Modem Relay and T38 disabled. X-cap not needed

002135: Aug 28 14:05:23.595: //104/B75A96E7800D/SIP/Info/sipSPIOutgoingCallSDP: Creating recv-only stream for outbound call

002136: Aug 28 14:05:23.595: //104/B75A96E7800D/SIP/Media/sipSPIProcessRtpSessions: No active streams.

002137: Aug 28 14:05:23.595: //104/B75A96E7800D/SIP/Info/sip_gw_pre_setup_add_sdp_container: SDP container added

002138: Aug 28 14:05:23.595: //104/B75A96E7800D/SIP/Info/sipSPIValidateGtd: Signal Forward disabled

002139: Aug 28 14:05:23.595: //104/B75A96E7800D/SIP/Info/sipSPIValidateTunnelData: RawMsg/QSIG Tunneling Not Enabled

002140: Aug 28 14:05:23.595: //104/B75A96E7800D/SIP/Info/sipSPIAddMLPPServicesInfo: No MLP Info available on incoming leg

002141: Aug 28 14:05:23.595: //104/B75A96E7800D/SIP/Info/sipSPIPreprocessUriFormat: Url cfg for 1: 2,phone-ctxt=FALSE

002142: Aug 28 14:05:23.595: //104/B75A96E7800D/SIP/Info/sipSPIAddCiscoGcid: Gcid value not set - not adding header.

002143: Aug 28 14:05:23.595: //104/B75A96E7800D/SIP/Info/sipSPIAddPrivacyandIdentityInfo: Removing "id" value from Privacy

002144: Aug 28 14:05:23.595: //104/B75A96E7800D/SIP/Info/sipSPICompareHistoryInfoWithMatchedDialpeer: call-route history-info CLI not enabled

002145: Aug 28 14:05:23.595: //104/B75A96E7800D/SIP/Info/sipSPI_ipip_set_history_info_header: No HI header recvd from container

002146: Aug 28 14:05:23.595: //-1/xxxxxxxxxxxx/SIP/Info/resolve_sig_ip_address_to_bind: calling reg_invoke_ip_first_hop()

002147: Aug 28 14:05:23.599: //-1/xxxxxxxxxxxx/SIP/Info/resolve_sig_ip_address_to_bind: calling ip_best_local_address()

002148: Aug 28 14:05:23.599: //-1/xxxxxxxxxxxx/SIP/Info/resolve_sig_ip_address_to_bind: return addr 192.168.10.1

002149: Aug 28 14:05:23.599: //104/B75A96E7800D/SIP/Info/sipSPIRscmsmAvail: Value returned by check is = 0

002150: Aug 28 14:05:23.599: //-1/xxxxxxxxxxxx/SIP/Info/resolve_sig_ip_address_to_bind: calling reg_invoke_ip_first_hop()

002151: Aug 28 14:05:23.599: //-1/xxxxxxxxxxxx/SIP/Info/resolve_sig_ip_address_to_bind: calling ip_best_local_address()

002152: Aug 28 14:05:23.599: //-1/xxxxxxxxxxxx/SIP/Info/resolve_sig_ip_address_to_bind: return addr 192.168.10.1

002153: Aug 28 14:05:23.599: //104/B75A96E7800D/SIP/Info/sipSPIUaddCcbToUACTable: ****Adding to UAC table.

002154: Aug 28 14:05:23.599: //104/B75A96E7800D/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x88B4C2A0 key=B75E3FD7-F2111E3-8160F81B-FAE07135@192.168.10.1

002155: Aug 28 14:05:23.599: //104/B75A96E7800D/SIP/Info/sipSPIUsetBillingProfile: sipCallId for billing records = B75E3FD7-F2111E3-8160F81B-FAE07135@192.168.10.1

002156: Aug 28 14:05:23.599: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 192.168.11.250,Port 5060, Transport 1, SentBy Port 5060

002157: Aug 28 14:05:23.599: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Converting TimeZone BST to SIP default timezone = GMT

002158: Aug 28 14:05:23.599: //104/B75A96E7800D/SIP/Event/Session-Timer/sipSTSLMain: Event: E_STSL_SESSION_REFRESH_REQ

002159: Aug 28 14:05:23.599: //104/B75A96E7800D/SIP/Event/Session-Timer/sipSTSLMain: dir:1, method:102, resp_code:0, container:8B9ED5C4

002160: Aug 28 14:05:23.599: //104/B75A96E7800D/SIP/Info/Session-Timer/sipSTSLSRReqSend: Session timer is not required

002161: Aug 28 14:05:23.599: //104/B75A96E7800D/SIP/Info/Session-Timer/sipSTSLMain:

        SE: 0;refresher:none peer refresher:none, flags:2000, posted event:E_STSL_INVALID_PEER_EVENT, reason:4

        Configured SE:1800, Configured Min-SE:1800

002162: Aug 28 14:05:23.599: //104/B75A96E7800D/SIP/Info/ccsip_offer_ans_handle_sent_sdp:

002163: Aug 28 14:05:23.599: //104/B75A96E7800D/SIP/Info/ccsip_offer_ans_process_event:

002164: Aug 28 14:05:23.599: //104/B75A96E7800D/SIP/State/ccsip_cnfsm_debugs: OA:cur_container:ccsip_offer_ans_main_container, cur_state:S_SIP_EARLY_DIALOG_IDLE, event:E_SIP_INVITE_SDP_SENT

002165: Aug 28 14:05:23.599: //104/B75A96E7800D/SIP/Info/ccsip_offer_ans_is_invite_offer_valid:  - 1

002166: Aug 28 14:05:23.599: //104/B75A96E7800D/SIP/Info/ccsip_offer_ans_common_offer_sent_hdlr:

002167: Aug 28 14:05:23.599: //104/B75A96E7800D/SIP/Info/ccsip_iwf_handle_network_event:

002168: Aug 28 14:05:23.599: //104/B75A96E7800D/SIP/Info/ccsip_iwf_process_event: 

002169: Aug 28 14:05:23.599: //104/B75A96E7800D/SIP/State/ccsip_cnfsm_debugs: IWF:cur_container:sip_iwf_default_early_dialog_container, cur_state:S_SIP_IWF_SDP_IDLE, event:E_SIP_IWF_EV_SENT_SDP

002170: Aug 28 14:05:23.599: //104/B75A96E7800D/SIP/Info/sip_iwf_def_ed_sent_sdp_offer_hdlr:

002171: Aug 28 14:05:23.599: //104/B75A96E7800D/SIP/State/ccsip_cnfsm_debugs: IWF:next_state:S_SIP_IWF_SDP_SENT_AWAIT_SDP

002172: Aug 28 14:05:23.599: //104/B75A96E7800D/SIP/State/ccsip_cnfsm_debugs: OA:next_state:S_SIP_EARLY_DIALOG_OFFER_SENT

002173: Aug 28 14:05:23.599: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIgetRegistrarHost: registrar is not configured

002174: Aug 28 14:05:23.599: //104/B75A96E7800D/SIP/Event/sipSPICreateRpid: Received Octet3A=0x83 -> Setting ;screen=yes ;privacy=off

SIP: (104) Group (a= group line) attribute, level 65535 instance 1 not found.

002175: Aug 28 14:05:23.599: //104/B75A96E7800D/SIP/Info/sipSPIGetCallExtensionSupported: anat enabled, src_sdp dont have anat

002176: Aug 28 14:05:23.599: //104/B75A96E7800D/SIP/Info/sipSPISendInvite: Associated container=0x8B9ED5C4 to Invite

002177: Aug 28 14:05:23.599: //104/B75A96E7800D/SIP/Transport/sipSPISendInvite: Sending Invite to the transport layer

002178: Aug 28 14:05:23.599: //104/B75A96E7800D/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Global configuration, Switch Transport is FALSE

002179: Aug 28 14:05:23.599: //104/B75A96E7800D/SIP/Transport/sipSPITransportSendMessage: msg=0x8BDD4D8C, addr=192.168.11.250, port=5060, sentBy_port=0, local_addr=, is_req=1, transport=1, switch=0, callBack=0x814A82CC

002180: Aug 28 14:05:23.599: //104/B75A96E7800D/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately

002181: Aug 28 14:05:23.603: //104/B75A96E7800D/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0

002182: Aug 28 14:05:23.603: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:192.168.11.250, rport:5060 with laddr:

002183: Aug 28 14:05:23.603: //104/B75A96E7800D/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x8BDD4D8C

002184: Aug 28 14:05:23.603: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x8BDD4D8C, addr=192.168.11.250, port=5060, local_addr=, connId=5 for UDP

002185: Aug 28 14:05:23.603: //104/B75A96E7800D/SIP/Info/sentInviteRequest: Sent Invite in state STATE_IDLE

002186: Aug 28 14:05:23.603: //-1/xxxxxxxxxxxx/SIP/Info/sentInviteRequest: Transaction active. Facilities will be queued.

002187: Aug 28 14:05:23.603: //104/B75A96E7800D/SIP/State/sipSPIChangeState: 0x88B4C2A0 : State change from (STATE_IDLE, SUBSTATE_NONE)  to (STATE_SENT_INVITE, SUBSTATE_NONE)

002188: Aug 28 14:05:23.603: //104/B75A96E7800D/SIP/Media/sipSPIAddStream: Adding stream 1 of type voice+dtmf (callid 104) to the VOIP RTP library

002189: Aug 28 14:05:23.603: //104/B75A96E7800D/SIP/Info/sipSPIValidateStreamAddrType: stream:1, Mode : 1

002190: Aug 28 14:05:23.603: //104/B75A96E7800D/SIP/Info/resolve_media_ip_address_to_bind: Media already bound, use existing source_media_ip_addr

002191: Aug 28 14:05:23.603: //104/B75A96E7800D/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 192.168.10.1

002192: Aug 28 14:05:23.603: //104/B75A96E7800D/SIP/Media/sipSPIUpdateRtcpSession: sipSPIUpdateRtcpSession for m-line 1

002193: Aug 28 14:05:23.603: //104/B75A96E7800D/SIP/Media/sipSPIUpdateRtcpSession: rtcp_session info

        laddr = 192.168.10.1, lport = 17978, raddr = 0.0.0.0, rport=0, do_rtcp=FALSE

        src_callid = 104, dest_callid = -1, stream type = voice+dtmf, stream direction = RECVONLY

        media_ip_addr =  - , vrf tableid = 0 media_addr_type = 1

002194: Aug 28 14:05:23.603: //104/B75A96E7800D/SIP/Media/sipSPIUpdateRtcpSession: No rtp session, creating a new one

002195: Aug 28 14:05:23.603: //104/B75A96E7800D/SIP/Info/sipSPICreateRtpSession: sess: 8BA16788 do_rtcp:0

002196: Aug 28 14:05:23.603: //104/B75A96E7800D/SIP/Media/sipSPICreateRtpSession: stun is disabled

002197: Aug 28 14:05:23.603: //104/B75A96E7800D/SIP/State/sipSPIChangeStreamState: Stream (callid =  104)  State changed from (STREAM_ADDING) to (STREAM_ACTIVE)

002198: Aug 28 14:05:23.603: //104/B75A96E7800D/SIP/Info/sipSPIUpdateCallEntry:

Call 104 set InfoType to SPEECH

002199: Aug 28 14:05:23.603: //104/B75A96E7800D/SIP/Msg/ccsipDisplayMsg:

Sent:

INVITE sip:1001@192.168.11.250:5060 SIP/2.0

Via: SIP/2.0/UDP 192.168.10.1:5060;x-route-tag="tgrp:ALL_BRI";branch=z9hG4bK3014BC

Remote-Party-ID: <sip:90XXX@192.168.10.1>;party=calling;screen=yes;privacy=off

From: <sip:90XXX@192.168.10.1>;tag=3B43AC-1C40

To: <sip:1001@192.168.11.250>

Date: Wed, 28 Aug 2013 14:05:23 GMT

Call-ID: B75E3FD7-F2111E3-8160F81B-FAE07135@192.168.10.1

Supported: 100rel,timer,resource-priority,replaces,sdp-anat

Min-SE:  1800

Cisco-Guid: 3076167399-0253825507-2148335646-2051178880

User-Agent: Cisco-SIPGateway/IOS-12.x

Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER

CSeq: 101 INVITE

Max-Forwards: 70

Timestamp: 1377698723

Contact: <sip:90XXX@192.168.10.1:5060>

Expires: 180

Allow-Events: telephone-event

Content-Type: application/sdp

Content-Disposition: session;handling=required

Content-Length: 215

v=0

o=CiscoSystemsSIP-GW-UserAgent 9792 4474 IN IP4 192.168.10.1

s=SIP Call

c=IN IP4 192.168.10.1

t=0 0

m=audio 17978 RTP/AVP 0 19

c=IN IP4 192.168.10.1

a=rtpmap:0 PCMU/8000

a=rtpmap:19 CN/8000

a=ptime:20

002200: Aug 28 14:05:23.611: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [192.168.11.250]:5060, local_address:[ - ]

002201: Aug 28 14:05:23.611: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1

002202: Aug 28 14:05:23.611: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0

002203: Aug 28 14:05:23.611: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog

002204: Aug 28 14:05:23.611: //104/B75A96E7800D/SIP/Msg/ccsipDisplayMsg:

Received:

SIP/2.0 100 Trying

Via: SIP/2.0/UDP 192.168.10.1:5060;x-route-tag="tgrp:ALL_BRI";branch=z9hG4bK3014BC

From: <sip:90XXX@192.168.10.1>;tag=3B43AC-1C40

To: <sip:1001@192.168.11.250>

Date: Wed, 28 Aug 2013 14:05:23 GMT

Call-ID: B75E3FD7-F2111E3-8160F81B-FAE07135@192.168.10.1

CSeq: 101 INVITE

Allow-Events: presence

Content-Length: 0

002205: Aug 28 14:05:23.611: //104/B75A96E7800D/SIP/Info/sipSPICheckResponseExt: INVITE response with no RSEQ - disable IS_REL1XX

002206: Aug 28 14:05:23.611: //104/B75A96E7800D/SIP/State/sipSPIChangeState: 0x88B4C2A0 : State change from (STATE_SENT_INVITE, SUBSTATE_NONE)  to (STATE_RECD_PROCEEDING, SUBSTATE_PROCEEDING_PROCEEDING)

002207: Aug 28 14:05:23.691: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [192.168.11.250]:5060, local_address:[ - ]

002208: Aug 28 14:05:23.691: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1

002209: Aug 28 14:05:23.691: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0

002210: Aug 28 14:05:23.691: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog

002211: Aug 28 14:05:23.691: //104/B75A96E7800D/SIP/Msg/ccsipDisplayMsg:

Received:

SIP/2.0 486 Busy here

Via: SIP/2.0/UDP 192.168.10.1:5060;x-route-tag="tgrp:ALL_BRI";branch=z9hG4bK3014BC

From: <sip:90XXX@192.168.10.1>;tag=3B43AC-1C40

To: <sip:1001@192.168.11.250>;tag=1056~c5bd5e1e-afbe-4b3e-b317-aec2cd78e4b1-24392312

Date: Wed, 28 Aug 2013 14:05:23 GMT

Call-ID: B75E3FD7-F2111E3-8160F81B-FAE07135@192.168.10.1

CSeq: 101 INVITE

Allow-Events: presence

Reason: Q.850;cause=17

Content-Length: 0

002212: Aug 28 14:05:23.691: //104/B75A96E7800D/SIP/Info/sipSPICheckResponseExt: INVITE response with no RSEQ - disable IS_REL1XX

002213: Aug 28 14:05:23.691: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentGTD: No GTD found in inbound container

002214: Aug 28 14:05:23.691: //104/B75A96E7800D/SIP/Info/ccsip_offer_ans_handle_call_active:

002215: Aug 28 14:05:23.691: //104/B75A96E7800D/SIP/Info/ccsip_offer_ans_process_event:

002216: Aug 28 14:05:23.691: //104/B75A96E7800D/SIP/State/ccsip_cnfsm_debugs: OA:cur_container:ccsip_offer_ans_main_container, cur_state:S_SIP_EARLY_DIALOG_OFFER_SENT, event:E_SIP_DIALOG_ESTD

002217: Aug 28 14:05:23.691: //104/B75A96E7800D/SIP/Info/ccsip_offer_ans_process_event: O/A - cnfsm ret 2

002218: Aug 28 14:05:23.691: //104/B75A96E7800D/SIP/Info/sipSPISendAck: Associated container=0x8B9ED884 to Ack

002219: Aug 28 14:05:23.691: //104/B75A96E7800D/SIP/Transport/sipSPISendAck: Sending ACK to the transport layer

002220: Aug 28 14:05:23.691: //104/B75A96E7800D/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Global configuration, Switch Transport is FALSE

002221: Aug 28 14:05:23.691: //104/B75A96E7800D/SIP/Transport/sipSPITransportSendMessage: msg=0x866DAD04, addr=192.168.11.250, port=5060, sentBy_port=0, local_addr=, is_req=1, transport=1, switch=0, callBack=0x0

002222: Aug 28 14:05:23.691: //104/B75A96E7800D/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately

002223: Aug 28 14:05:23.691: //104/B75A96E7800D/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0

002224: Aug 28 14:05:23.691: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:192.168.11.250, rport:5060 with laddr:

002225: Aug 28 14:05:23.691: //104/B75A96E7800D/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x866DAD04

002226: Aug 28 14:05:23.691: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x866DAD04, addr=192.168.11.250, port=5060, local_addr=, connId=5 for UDP

002227: Aug 28 14:05:23.695: //104/B75A96E7800D/SIP/Info/act_recdproc_new_message_response: Received a 4/5/6xx message with StatusCode: 486

002228: Aug 28 14:05:23.695: //104/B75A96E7800D/SIP/Info/ccsip_set_release_source_for_peer: ownCallId[104], src[4]

002229: Aug 28 14:05:23.695: //104/B75A96E7800D/SIP/Info/sipSPIInitiateDisconnect: Initiate call disconnect(17) for outgoing call

002230: Aug 28 14:05:23.695: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentQSIG: No QSIG Body found in inbound container

002231: Aug 28 14:05:23.695: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentQ931: No RawMsg Body found in inbound container

002232: Aug 28 14:05:23.695: //104/B75A96E7800D/SIP/Info/ccsip_ipip_media_service_get_event_data: Event id = 26

002233: Aug 28 14:05:23.695: //104/B75A96E7800D/SIP/Info/sipSPI_ipip_antiTrombone: Entered Antitrombone service

002234: Aug 28 14:05:23.695: //104/B75A96E7800D/SIP/Info/sipSPI_ipip_antiTrombone: Antitrombone service not configured

002235: Aug 28 14:05:23.695: //104/B75A96E7800D/SIP/State/sipSPIChangeState: 0x88B4C2A0 : State change from (STATE_RECD_PROCEEDING, SUBSTATE_PROCEEDING_PROCEEDING)  to (STATE_DISCONNECTING, SUBSTATE_NONE)

002236: Aug 28 14:05:23.695: //104/B75A96E7800D/SIP/Info/ccsip_call_statistics: Requesting stats for callid=104

002237: Aug 28 14:05:23.695: //104/B75A96E7800D/SIP/Info/ccsip_call_statistics: Stats request failed for callid=104, dstCallID=-1, rc=-7

002238: Aug 28 14:05:23.695: //104/B75A96E7800D/SIP/Info/ccsip_ipip_media_service_get_event_data: Event id = 26

002239: Aug 28 14:05:23.695: //104/B75A96E7800D/SIP/Info/sipSPI_ipip_antiTrombone: Entered Antitrombone service

002240: Aug 28 14:05:23.695: //104/B75A96E7800D/SIP/Info/sipSPI_ipip_antiTrombone: Antitrombone service not configured

002241: Aug 28 14:05:23.695: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_DISCONNECT

002242: Aug 28 14:05:23.695: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 8

002243: Aug 28 14:05:23.695: //104/B75A96E7800D/SIP/Event/Session-Timer/sipSTSLMain: Event: E_STSL_SPI_EVENT

002244: Aug 28 14:05:23.695: //104/B75A96E7800D/SIP/Info/Session-Timer/sipSTSLMain:

        SE: 0;refresher:none peer refresher:none, flags:2000, posted event:E_STSL_INVALID_PEER_EVENT, reason:4

        Configured SE:1800, Configured Min-SE:1800

002245: Aug 28 14:05:23.695: //104/B75A96E7800D/SIP/Info/sipSPIIcpifUpdate: CallState: 2 Playout: 0 DiscTime:388404 ConnTime 0

002246: Aug 28 14:05:23.695: //104/B75A96E7800D/SIP/Media/sipSPIDestroyRtpSession: stream:8BDD5478

002247: Aug 28 14:05:23.699: //104/B75A96E7800D/SIP/State/sipSPIChangeState: 0x88B4C2A0 : State change from (STATE_DISCONNECTING, SUBSTATE_NONE)  to (STATE_DEAD, SUBSTATE_NONE)

002248: Aug 28 14:05:23.699: //104/B75A96E7800D/SIP/Call/sipSPICallInfo:

The Call Setup Information is:

Call Control Block (CCB) : 0x88B4C2A0

State of The Call        : STATE_DEAD

TCP Sockets Used         : NO

Calling Number           : 90XXX

Called Number            : 1001

Source IP Address (Sig  ): 192.168.10.1

Destn SIP Req Addr:Port  : 192.168.11.250:5060

Destn SIP Resp Addr:Port : 192.168.11.250:5060

Destination Name         : 192.168.11.250

002249: Aug 28 14:05:23.699: //104/B75A96E7800D/SIP/Call/sipSPIMediaCallInfo:

Number of Media Streams: 1

Media Stream             : 1

Negotiated Codec         : No Codec  

Negotiated Codec Bytes   : 0

Nego. Codec payload      : 255 (tx), 255 (rx)

Negotiated Dtmf-relay    : 0

Dtmf-relay Payload       : 0 (tx), 0 (rx)

Source IP Address (Media): 192.168.10.1

Source IP Port    (Media): 17978

Destn  IP Address (Media):  -

Destn  IP Port    (Media): 0

Orig Destn IP Address:Port (Media): [ - ]:0

002250: Aug 28 14:05:23.699: //104/B75A96E7800D/SIP/Call/sipSPICallInfo:

Disconnect Cause (CC)    : 17

Disconnect Cause (SIP)   : 486

002251: Aug 28 14:05:23.699: //104/B75A96E7800D/SIP/Info/sipSPIUdeleteccCallIdFromTable: Removing call id 68

002252: Aug 28 14:05:23.707: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:

Sent:

ACK sip:1001@192.168.11.250:5060 SIP/2.0

Via: SIP/2.0/UDP 192.168.10.1:5060;x-route-tag="tgrp:ALL_BRI";branch=z9hG4bK3014BC

From: <sip:90XXX@192.168.10.1>;tag=3B43AC-1C40

To: <sip:1001@192.168.11.250>;tag=1056~c5bd5e1e-afbe-4b3e-b317-aec2cd78e4b1-24392312

Date: Wed, 28 Aug 2013 14:05:23 GMT

Call-ID: B75E3FD7-F2111E3-8160F81B-FAE07135@192.168.10.1

Max-Forwards: 70

CSeq: 101 ACK

Allow-Events: telephone-event

Content-Length: 0

I have checked the incoming CSS on the trunk, but looks okay and I can dial to 1001 directly from CUCM so doesn't seem like a permissions issue and have reset the trunk. I've checked the Call Manager traces and can see the call coming in and the CUCM sends back a 486 busy, but I can't figure out why.

SIP.png

Is there anything else I can check?

Thanks

Sean

175
Views
0
Helpful
0
Replies
CreatePlease login to create content