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.
Is there anything else I can check?
Thanks
Sean
