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

CME IOS 15 SIP trunk with SPA9000

Dear Sirs,

We are trying to integrate CME ISR G2 with a Linksys SPA9000 IP PBX.

We can place calls from the SPA to a CME phone but not vice versa.

We changed the parameter on the SPA to not register the trunk.

Any other clues why there calls can not be made using a Cisco phone to a linksys one?

Thanks in advance,

Nick

7 REPLIES
Hall of Fame Super Gold

CME IOS 15 SIP trunk with SPA9000

Take "debug ccsip message" with "term mon". Do not enable other debugs. Do not use attachments.

New Member

CME IOS 15 SIP trunk with SPA9000

Dear Paolo,

Below is a debug ccsip all

Jan  9 14:47:22.722: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDeleteContextFromTable: Context for key=[2292] removed.

Jan  9 14:47:22.722: //2465/98AFC3AB82C5/SIP/Info/sipSPIUdeleteCcbFromUACTable: ****Deleting from UAC table.

Jan  9 14:47:22.722: //2465/98AFC3AB82C5/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x31853220 key=992F54CA-3A0711E1-82CAEEFB-5980959F@192.168.0.250

Jan  9 14:47:22.722: //2465/98AFC3AB82C5/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd

Jan  9 14:47:22.722: //2465/98AFC3AB82C5/SIP/Info/sipSPI_ipip_free_codec_profile: Codec Profiles Freed

Jan  9 14:47:22.722: //2465/98AFC3AB82C5/SIP/Info/ccsip_offer_ans_delete:

Jan  9 14:47:22.722: //2465/98AFC3AB82C5/SIP/Info/ccsip_iwf_delete: 

Jan  9 14:47:22.722: //2465/98AFC3AB82C5/SIP/Info/sipSPIUfreeOneCCB: Freeing ccb 31853220

Jan  9 14:47:25.010: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAddContextToTable: Added context(0x31853220) with key=[2294] to table

Jan  9 14:47:25.010: //-1/000000000000/SIP/Info/ccsip_offer_ans_init:

Jan  9 14:47:25.010: //-1/000000000000/SIP/Info/ccsip_iwf_init: 

Jan  9 14:47:25.010: //-1/000000000000/SIP/Info/ccsip_ipip_media_service_init:

Jan  9 14:47:25.010: //-1/000000000000/SIP/Info/sipSPI_ipip_vcc_Initialization:  Entry...

Jan  9 14:47:25.010: //2469/000000000000/SIP/State/sipSPIChangeState: 0x31853220 : State change from (STATE_NONE, SUBSTATE_NONE)  to (STATE_IDLE, SUBSTATE_NONE)

Jan  9 14:47:25.010: //2469/000000000000/SIP/Info/ccsip_call_setup_request: Set Protocol information

Jan  9 14:47:25.010: //2469/000000000000/SIP/Info/ccsip_iwf_handle_peer_event:

Jan  9 14:47:25.010: //2469/000000000000/SIP/Info/ccsip_iwf_map_ccapi_event_to_iwf_event: Event Category: 1, Event Id: 174

Jan  9 14:47:25.010: //2469/000000000000/SIP/Info/ccsip_iwf_process_event: 

Jan  9 14:47:25.010: //2469/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

Jan  9 14:47:25.010: //2469/000000000000/SIP/State/ccsip_cnfsm_debugs: IWF:new_container:sip_iwf_main_container

Jan  9 14:47:25.010: //2469/000000000000/SIP/Info/ccsip_get_int_type_frm_set_mode_ev:

Jan  9 14:47:25.010: //2469/000000000000/SIP/Info/is_mode_sip_sip_md:

Jan  9 14:47:25.010: //2469/000000000000/SIP/Info/ccsip_get_int_type_frm_set_mode_ev:

Jan  9 14:47:25.010: //2469/000000000000/SIP/Info/is_mode_sip_sip_ed:

Jan  9 14:47:25.010: //2469/000000000000/SIP/Info/ccsip_get_int_type_frm_set_mode_ev:

Jan  9 14:47:25.010: //2469/000000000000/SIP/Info/is_mode_sip_h32x_in_set_mode:

Jan  9 14:47:25.010: //2469/000000000000/SIP/Info/ccsip_get_int_type_frm_set_mode_ev:

Jan  9 14:47:25.010: //2469/000000000000/SIP/Info/is_mode_sip_h323_in_set_mode:

Jan  9 14:47:25.010: //2469/000000000000/SIP/Info/ccsip_get_int_type_frm_set_mode_ev:

Jan  9 14:47:25.010: //2469/000000000000/SIP/Info/is_mode_sip_sccp_in_set_mode:

Jan  9 14:47:25.010: //2469/000000000000/SIP/Info/ccsip_get_int_type_frm_set_mode_ev:

Jan  9 14:47:25.010: //2469/000000000000/SIP/Info/is_mode_sip_sccp_in_set_mode:

Jan  9 14:47:25.010: //2469/000000000000/SIP/Info/sip_iwf_def_set_mode_hdlr: Setting SPI mode to SIP-TDM

Jan  9 14:47:25.010: //2469/000000000000/SIP/State/ccsip_cnfsm_debugs: IWF:new_container:sip_iwf_sccp_early_dialog_container

Jan  9 14:47:25.010: //2469/000000000000/SIP/State/ccsip_cnfsm_debugs: IWF:next_state:CNFSM_NO_STATE_CHANGE

Jan  9 14:47:25.010: //2469/000000000000/SIP/Info/ccsip_iwf_handle_peer_event: Return value : SIP_IWF_SUCCESS

Jan  9 14:47:25.010: //2469/000000000000/SIP/Info/ccsip_iwf_handle_peer_event:

Jan  9 14:47:25.010: //2469/000000000000/SIP/Info/ccsip_iwf_map_ccapi_event_to_iwf_event: Event Category: 3, Event Id: 5

Jan  9 14:47:25.010: //2469/000000000000/SIP/Info/ccsip_iwf_process_event: 

Jan  9 14:47:25.014: //2469/000000000000/SIP/State/ccsip_cnfsm_debugs: IWF:cur_container:sip_iwf_sccp_early_dialog_container, cur_state:S_SIP_IWF_SDP_IDLE, event:E_SIP_IWF_EV_SET_FLOW_MODE

Jan  9 14:47:25.014: //2469/000000000000/SIP/State/ccsip_cnfsm_debugs: IWF:new_container:sip_iwf_main_container

Jan  9 14:47:25.014: //2469/000000000000/SIP/Info/is_fa2ft_md_flow_mode_transition:

Jan  9 14:47:25.014: //2469/000000000000/SIP/Info/is_fa2ft_flow_mode_transition:

Jan  9 14:47:25.014: //2469/000000000000/SIP/Info/ccsip_get_flow_mode_frm_set_flow_mode_ev:

Jan  9 14:47:25.014: //2469/000000000000/SIP/Info/is_fa2ft_flow_mode_transition:

Jan  9 14:47:25.014: //2469/000000000000/SIP/Info/ccsip_get_flow_mode_frm_set_flow_mode_ev:

Jan  9 14:47:25.014: //2469/000000000000/SIP/Info/ccsip_iwf_process_event: IWF - cnfsm ret 2

Jan  9 14:47:25.014: //2469/000000000000/SIP/Info/ccsip_iwf_handle_peer_event: Return value : SIP_IWF_SUCCESS

Jan  9 14:47:25.014: //2469/000000000000/SIP/Info/ccsip_call_setup_request: Before processing SETUP REQccb->pld.flags_ipip = 200

Jan  9 14:47:25.014: //2469/000000000000/SIP/Info/ccsip_call_setup_request: After processing SETUP REQccb->pld.flags_ipip = 200

Jan  9 14:47:25.014: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetOutboundHostAndDestHostPrivate: CCSIP: target_host : 192.168.0.155 target_port : 5060

Jan  9 14:47:25.014: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_SETUP

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/Info/ccsip_call_setup_request: Incrementing call counter to [1] in dial-peer [101]

Jan  9 14:47:25.014: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 2

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/Info/sipSPIUaddccCallIdToTable: Adding call id 9A5 to table

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/Info/sipSPIGetCallConfig: preferred_codec set[0] type :No Codec    bytes: 0

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/Info/sipSPIGetCallConfig: Media forking disabled

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/Info/sipSPIGetCallConfig: Media Antitrombone disabled

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/Info/sipSPICanSetFallbackFlag: Local Fallback is not active

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/Info/sipSPISetMediaFlowMode: Storing the configured mode as FLOW-THROUGH

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/Info/sipSPISetMediaFlowMode: xcoder high-density disabled

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/Info/sipSPISetMediaFlowMode: Flow Mode set to FLOW_THROUGH

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/Info/sipSPIGetCallConfig: Checking Video Type Rate=-1 video_codec_allowed=1F

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/Media/sipSPICopyStunConfigFromPeerToCCB: Firewall traversal is not enabled

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/Info/sipSPIGetModemInfoPerCall: peer_callID=2468

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/Info/sipSPIGetModemConfig:

From Config: Modem NSE payload = 100, Passthrough = 4, Modem relay = 0, Gw-Xid = 1

SPRT latency 200, SPRT Retries = 12, Dict Size = 1024

String Len = 32, Compress dir = 3

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/Info/sipSPIGetCallConfig: Media forking disabled

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/Info/sipSPISetOverlapConfiguration: Overlap signaling: FALSE: Endpt: SIP Trunk

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/Info/sipSPI_ipip_GetHdrPassthruCfg: Hdr passthrough config:1 tag:0

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/Info/sipSPI_ipip_GetCopyListCfg: Copy-list config:2 tag:0

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/Info/sipSPI_ipip_build_consolidated_header_list: Both passthru and copylist are disabled

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/Info/sipSPIValidateAndCopyOutboundHost: CCSIP: copy target_host to outbound_host

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/Info/preprocessSetup:

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

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/Info/ccsip_iwf_process_event: 

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/State/ccsip_cnfsm_debugs: IWF:cur_container:sip_iwf_sccp_early_dialog_container, cur_state:S_SIP_IWF_SDP_IDLE, event:E_SIP_IWF_EV_INIT_CALL_SETUP

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/State/ccsip_cnfsm_debugs: IWF:new_container:sip_iwf_main_container

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/Info/ccsip_iwf_process_event: IWF - cnfsm ret 2

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/Info/sipSPIValidateStreamAddrType: stream:1, Mode : 1

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 192.168.0.250

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/Info/resolve_sig_ip_address_to_bind: signaling bind address : 192.168.0.250

Jan  9 14:47:25.014: //-1/xxxxxxxxxxxx/SIP/Media/sipSPIReserveRtpPort: reserved port 19160 for stream 1

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/Media/sipSPIAddSDPMediaPayload: Preferred method of dtmf relay is: 6, with payload: 101

Jan  9 14:47:25.014: //-1/xxxxxxxxxxxx/SIP/Info/convert_codec_bytes_to_ptime: Values :Codec: g711ulaw codecbytes :160, ptime: 20

Jan  9 14:47:25.014: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetMediaDirectionForStream: Setting Media direction SENDRECV for stream 1

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/Info/sip_generate_sdp_xcaps_list: Modem Relay and T38 disabled. X-cap not needed

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/Info/sipSPIOutgoingCallSDP: Creating recv-only stream for outbound call

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/Media/sipSPIProcessRtpSessions: No active streams.

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/Info/sip_gw_pre_setup_add_sdp_container: SDP container added

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/Info/sipSPIValidateGtd: Signal Forward disabled

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/Info/sipSPIValidateTunnelData: RawMsg/QSIG Tunneling Not Enabled

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/Info/sipSPIAddMLPPServicesInfo: No MLP Info available on incoming leg

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/Info/sipSPIPreprocessUriFormat: Url cfg for 1: 2,phone-ctxt=FALSE

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/Info/sipSPIAddCiscoGcid: Gcid value not set - not adding header.

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/Info/sipSPIAddPrivacyandIdentityInfo: Removing "id" value from Privacy

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/Info/sipSPICompareHistoryInfoWithMatchedDialpeer: call-route history-info CLI not enabled

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/Info/sipSPI_ipip_set_history_info_header: No HI header recvd from container

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/Info/resolve_sig_ip_address_to_bind: signaling bind address : 192.168.0.250

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/Info/sipSPIRscmsmAvail: Value returned by check is = 0

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/Info/resolve_sig_ip_address_to_bind: signaling bind address : 192.168.0.250

Jan  9 14:47:25.014: //2469/AD3510ED82D1/SIP/Info/sipSPIUaddCcbToUACTable: ****Adding to UAC table.

Jan  9 14:47:25.018: //2469/AD3510ED82D1/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x31853220 key=ADA2EE8A-3A0711E1-82D6EEFB-5980959F@192.168.0.250

Jan  9 14:47:25.018: //2469/AD3510ED82D1/SIP/Info/sipSPIUsetBillingProfile: sipCallId for billing records = ADA2EE8A-3A0711E1-82D6EEFB-5980959F@192.168.0.250

Jan  9 14:47:25.018: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 192.168.0.155,Port 5060, Transport 1, SentBy Port 5060

Jan  9 14:47:25.018: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Clock Time Zone is UTC, same as GMT: Using GMT

Jan  9 14:47:25.018: //2469/AD3510ED82D1/SIP/Event/Session-Timer/sipSTSLMain: Event: E_STSL_SESSION_REFRESH_REQ

Jan  9 14:47:25.018: //2469/AD3510ED82D1/SIP/Event/Session-Timer/sipSTSLMain: dir:1, method:102, resp_code:0, container:2C2C2AB0

Jan  9 14:47:25.018: //2469/AD3510ED82D1/SIP/Info/Session-Timer/sipSTSLSRReqSend: Session timer is not required

Jan  9 14:47:25.018: //2469/AD3510ED82D1/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

Jan  9 14:47:25.018: //2469/AD3510ED82D1/SIP/Info/ccsip_offer_ans_handle_sent_sdp:

Jan  9 14:47:25.018: //2469/AD3510ED82D1/SIP/Info/ccsip_offer_ans_process_event:

Jan  9 14:47:25.018: //2469/AD3510ED82D1/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

Jan  9 14:47:25.018: //2469/AD3510ED82D1/SIP/Info/ccsip_offer_ans_is_invite_offer_valid:  - 1

Jan  9 14:47:25.018: //2469/AD3510ED82D1/SIP/Info/ccsip_offer_ans_common_offer_sent_hdlr:

Jan  9 14:47:25.018: //2469/AD3510ED82D1/SIP/Info/ccsip_iwf_handle_network_event:

Jan  9 14:47:25.018: //2469/AD3510ED82D1/SIP/Info/ccsip_iwf_process_event: 

Jan  9 14:47:25.018: //2469/AD3510ED82D1/SIP/State/ccsip_cnfsm_debugs: IWF:cur_container:sip_iwf_sccp_early_dialog_container, cur_state:S_SIP_IWF_SDP_IDLE, event:E_SIP_IWF_EV_SENT_SDP

Jan  9 14:47:25.018: //2469/AD3510ED82D1/SIP/Info/is_sent_sccp_do_video_inactive:

Jan  9 14:47:25.018: //2469/AD3510ED82D1/SIP/Info/is_mode_sip_sccp_do_video:

Jan  9 14:47:25.018: //2469/AD3510ED82D1/SIP/Info/is_mode_sip_sccp_do_video:

Jan  9 14:47:25.018: //2469/AD3510ED82D1/SIP/Info/sip_iwf_def_ed_sent_sdp_offer_hdlr:

Jan  9 14:47:25.018: //2469/AD3510ED82D1/SIP/State/ccsip_cnfsm_debugs: IWF:next_state:S_SIP_IWF_SDP_SENT_AWAIT_SDP

Jan  9 14:47:25.018: //2469/AD3510ED82D1/SIP/State/ccsip_cnfsm_debugs: OA:next_state:S_SIP_EARLY_DIALOG_OFFER_SENT

Jan  9 14:47:25.018: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIgetRegistrarHost: registrar is not configured

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

Jan  9 14:47:25.018: //2469/AD3510ED82D1/SIP/Info/sipSPIGetCallExtensionSupported: anat enabled, src_sdp dont have anat

Jan  9 14:47:25.018: //2469/AD3510ED82D1/SIP/Info/sipSPISendInvite: Associated container=0x2C2C2AB0 to Invite

Jan  9 14:47:25.018: //2469/AD3510ED82D1/SIP/Transport/sipSPISendInvite: Sending Invite to the transport layer

Jan  9 14:47:25.018: //2469/AD3510ED82D1/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Global configuration, Switch Transport is FALSE

Jan  9 14:47:25.018: //2469/AD3510ED82D1/SIP/Transport/sipSPITransportSendMessage: msg=0x30A0EC1C, addr=192.168.0.155, port=5060, sentBy_port=0, local_addr=192.168.0.250, is_req=1, transport=1, switch=0, callBack=0x251BAD08

Jan  9 14:47:25.018: //2469/AD3510ED82D1/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately

Jan  9 14:47:25.018: //2469/AD3510ED82D1/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0

Jan  9 14:47:25.018: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:192.168.0.155, rport:5060 with laddr:192.168.0.250

Jan  9 14:47:25.018: //2469/AD3510ED82D1/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x30A0EC1C

Jan  9 14:47:25.018: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x30A0EC1C, addr=192.168.0.155, port=5060, local_addr=192.168.0.250, connId=2 for UDP

Jan  9 14:47:25.018: //2469/AD3510ED82D1/SIP/Info/sentInviteRequest: Sent Invite in state STATE_IDLE

Jan  9 14:47:25.018: //-1/xxxxxxxxxxxx/SIP/Info/sentInviteRequest: Transaction active. Facilities will be queued.

Jan  9 14:47:25.018: //2469/AD3510ED82D1/SIP/State/sipSPIChangeState: 0x31853220 : State change from (STATE_IDLE, SUBSTATE_NONE)  to (STATE_SENT_INVITE, SUBSTATE_NONE)

Jan  9 14:47:25.018: //2469/AD3510ED82D1/SIP/Media/sipSPIAddStream: Adding stream 1 of type voice+dtmf (callid 2469) to the VOIP RTP library

Jan  9 14:47:25.018: //2469/AD3510ED82D1/SIP/Info/sipSPIValidateStreamAddrType: stream:1, Mode : 1

Jan  9 14:47:25.018: //2469/AD3510ED82D1/SIP/Info/resolve_media_ip_address_to_bind: Media already bound, use existing source_media_ip_addr

Jan  9 14:47:25.018: //2469/AD3510ED82D1/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 192.168.0.250

Jan  9 14:47:25.018: //2469/AD3510ED82D1/SIP/Media/sipSPIUpdateRtcpSession: sipSPIUpdateRtcpSession for m-line 1

Jan  9 14:47:25.018: //2469/AD3510ED82D1/SIP/Media/sipSPIUpdateRtcpSession: rtcp_session info

    laddr = 192.168.0.250, lport = 19160, raddr = 0.0.0.0, rport=0, do_rtcp=FALSE

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

    media_ip_addr =  - , vrf tableid = 0 media_addr_type = 1

Jan  9 14:47:25.018: //2469/AD3510ED82D1/SIP/Media/sipSPIUpdateRtcpSession: No rtp session, creating a new one

Jan  9 14:47:25.018: //2469/AD3510ED82D1/SIP/Info/sipSPICreateRtpSession: sess: 2B8688C4 do_rtcp:0

Jan  9 14:47:25.018: //2469/AD3510ED82D1/SIP/Media/sipSPICreateRtpSession: stun is disabled

Jan  9 14:47:25.018: //2469/AD3510ED82D1/SIP/State/sipSPIChangeStreamState: Stream (callid =  2469)  State changed from (STREAM_ADDING) to (STREAM_ACTIVE)

Jan  9 14:47:25.018: //2469/AD3510ED82D1/SIP/Info/sipSPIUpdateCallEntry:

Call 2469 set InfoType to SPEECH

Jan  9 14:47:25.018: //2469/AD3510ED82D1/SIP/Msg/ccsipDisplayMsg:

Sent:

INVITE sip:745@192.168.0.155:5060 SIP/2.0

Via: SIP/2.0/UDP 192.168.0.250:5060;branch=z9hG4bK109491B

From: "GM" <2101>;tag=1647BF4-1678

To: <745>

Date: Mon, 09 Jan 2012 14:47:25 GMT

Call-ID: ADA2EE8A-3A0711E1-82D6EEFB-5980959F@192.168.0.250

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

Min-SE:  1800

Cisco-Guid: 2905936109-0973541857-2194796283-1501599135

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: 1326120445

Contact: <2101>

Expires: 180

Allow-Events: telephone-event

Content-Type: application/sdp

Content-Disposition: session;handling=required

Content-Length: 299

v=0

o=CiscoSystemsSIP-GW-UserAgent 8073 5726 IN IP4 192.168.0.250

s=SIP Call

c=IN IP4 192.168.0.250

t=0 0

m=audio 19160 RTP/AVP 0 100 101

c=IN IP4 192.168.0.250

a=rtpmap:0 PCMU/8000

a=rtpmap:100 X-NSE/8000

a=fmtp:100 192-194

a=rtpmap:101 telephone-event/8000

a=fmtp:101 0-16

a=ptime:20

Jan  9 14:47:25.026: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [192.168.0.155]:5060, local_address:[192.168.0.250]

Jan  9 14:47:25.026: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1

Jan  9 14:47:25.026: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x2AF65B4C

Jan  9 14:47:25.026: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessNewConnMsg: gConnTab=0x2AF65B4C, addr=192.168.0.155, port=5060, local_addr=192.168.0.250, connid=2, transport=UDP

Jan  9 14:47:25.026: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog

Jan  9 14:47:25.026: //2469/AD3510ED82D1/SIP/Msg/ccsipDisplayMsg:

Received:

SIP/2.0 100 Trying

To: <745>

From: "GM" <2101>;tag=1647BF4-1678

Call-ID: ADA2EE8A-3A0711E1-82D6EEFB-5980959F@192.168.0.250

CSeq: 101 INVITE

Via: SIP/2.0/UDP 192.168.0.250:5060;branch=z9hG4bK109491B;rport=54412

Timestamp: 1326120445

Server: Linksys/SPA9000-6.1.5

Allow-Events: talk, hold, conference

Content-Length: 0

Jan  9 14:47:25.026: //2469/AD3510ED82D1/SIP/Info/sipSPICheckResponseExt: INVITE response with no RSEQ - disable IS_REL1XX

Jan  9 14:47:25.026: //2469/AD3510ED82D1/SIP/State/sipSPIChangeState: 0x31853220 : State change from (STATE_SENT_INVITE, SUBSTATE_NONE)  to (STATE_RECD_PROCEEDING, SUBSTATE_PROCEEDING_PROCEEDING)

Jan  9 14:47:25.030: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [192.168.0.155]:5060, local_address:[192.168.0.250]

Jan  9 14:47:25.030: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1

Jan  9 14:47:25.030: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x2AF65B4C

Jan  9 14:47:25.030: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessNewConnMsg: gConnTab=0x2AF65B4C, addr=192.168.0.155, port=5060, local_addr=192.168.0.250, connid=2, transport=UDP

Jan  9 14:47:25.030: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog

Jan  9 14:47:25.030: //2469/AD3510ED82D1/SIP/Msg/ccsipDisplayMsg:

Received:

SIP/2.0 486 Busy Here

To: <745>;tag=d9950e59a7eb5288i2

From: "GM" <2101>;tag=1647BF4-1678

Call-ID: ADA2EE8A-3A0711E1-82D6EEFB-5980959F@192.168.0.250

CSeq: 101 INVITE

Via: SIP/2.0/UDP 192.168.0.250:5060;branch=z9hG4bK109491B;rport=54412

Timestamp: 1326120445

Server: Linksys/SPA9000-6.1.5

Allow-Events: talk, hold, conference

Content-Length: 0

Jan  9 14:47:25.030: //2469/AD3510ED82D1/SIP/Info/sipSPICheckResponseExt: INVITE response with no RSEQ - disable IS_REL1XX

Jan  9 14:47:25.030: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentGTD: No GTD found in inbound container

Jan  9 14:47:25.030: //2469/AD3510ED82D1/SIP/Info/ccsip_offer_ans_handle_call_active:

Jan  9 14:47:25.030: //2469/AD3510ED82D1/SIP/Info/ccsip_offer_ans_process_event:

Jan  9 14:47:25.030: //2469/AD3510ED82D1/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

Jan  9 14:47:25.030: //2469/AD3510ED82D1/SIP/Info/ccsip_offer_ans_process_event: O/A - cnfsm ret 2

Jan  9 14:47:25.030: //2469/AD3510ED82D1/SIP/Info/sipSPISendAck: Associated container=0x2C2C0748 to Ack

Jan  9 14:47:25.030: //2469/AD3510ED82D1/SIP/Transport/sipSPISendAck: Sending ACK to the transport layer

Jan  9 14:47:25.030: //2469/AD3510ED82D1/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Global configuration, Switch Transport is FALSE

Jan  9 14:47:25.030: //2469/AD3510ED82D1/SIP/Transport/sipSPITransportSendMessage: msg=0x32633380, addr=192.168.0.155, port=5060, sentBy_port=0, local_addr=192.168.0.250, is_req=1, transport=1, switch=0, callBack=0x0

Jan  9 14:47:25.030: //2469/AD3510ED82D1/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately

Jan  9 14:47:25.030: //2469/AD3510ED82D1/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0

Jan  9 14:47:25.030: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:192.168.0.155, rport:5060 with laddr:192.168.0.250

Jan  9 14:47:25.030: //2469/AD3510ED82D1/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x32633380

Jan  9 14:47:25.030: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x32633380, addr=192.168.0.155, port=5060, local_addr=192.168.0.250, connId=2 for UDP

Jan  9 14:47:25.030: //2469/AD3510ED82D1/SIP/Info/act_recdproc_new_message_response: Received a 4/5/6xx message with StatusCode: 486

Jan  9 14:47:25.030: //2469/AD3510ED82D1/SIP/Info/ccsip_set_release_source_for_peer: ownCallId[2469], src[4]

Jan  9 14:47:25.030: //2469/AD3510ED82D1/SIP/Info/sipSPIInitiateDisconnect: Initiate call disconnect(17) for outgoing call

Jan  9 14:47:25.030: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentQSIG: No QSIG Body found in inbound container

Jan  9 14:47:25.030: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentQ931: No RawMsg Body found in inbound container

Jan  9 14:47:25.030: //2469/AD3510ED82D1/SIP/Info/ccsip_ipip_media_service_get_event_data: Event id = 26

Jan  9 14:47:25.030: //2469/AD3510ED82D1/SIP/Info/sipSPI_ipip_antiTrombone: Entered Antitrombone service

Jan  9 14:47:25.030: //2469/AD3510ED82D1/SIP/Info/sipSPI_ipip_antiTrombone: Antitrombone service not configured

Jan  9 14:47:25.030: //2469/AD3510ED82D1/SIP/State/sipSPIChangeState: 0x31853220 : State change from (STATE_RECD_PROCEEDING, SUBSTATE_PROCEEDING_PROCEEDING)  to (STATE_DISCONNECTING, SUBSTATE_NONE)

Jan  9 14:47:25.030: //2469/AD3510ED82D1/SIP/Info/ccsip_call_statistics: Requesting stats for callid=2469

Jan  9 14:47:25.030: //2469/AD3510ED82D1/SIP/Info/ccsip_call_statistics: Stats request failed for callid=2469, dstCallID=-1, rc=-7

Jan  9 14:47:25.030: //2469/AD3510ED82D1/SIP/Info/ccsip_ipip_media_service_get_event_data: Event id = 26

Jan  9 14:47:25.030: //2469/AD3510ED82D1/SIP/Info/sipSPI_ipip_antiTrombone: Entered Antitrombone service

Jan  9 14:47:25.030: //2469/AD3510ED82D1/SIP/Info/sipSPI_ipip_antiTrombone: Antitrombone service not configured

Jan  9 14:47:25.030: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_DISCONNECT

Jan  9 14:47:25.030: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 8

Jan  9 14:47:25.030: //2469/AD3510ED82D1/SIP/Event/Session-Timer/sipSTSLMain: Event: E_STSL_SPI_EVENT

Jan  9 14:47:25.030: //2469/AD3510ED82D1/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

Jan  9 14:47:25.030: //2469/AD3510ED82D1/SIP/Info/sipSPIIcpifUpdate: CallState: 2 Playout: 0 DiscTime:2336256 ConnTime 0

Jan  9 14:47:25.030: //2469/AD3510ED82D1/SIP/Media/sipSPIDestroyRtpSession: stream:30E12D0C

Jan  9 14:47:25.030: //2469/AD3510ED82D1/SIP/State/sipSPIChangeState: 0x31853220 : State change from (STATE_DISCONNECTING, SUBSTATE_NONE)  to (STATE_DEAD, SUBSTATE_NONE)

Jan  9 14:47:25.030: //2469/AD3510ED82D1/SIP/Call/sipSPICallInfo:

The Call Setup Information is:

Call Control Block (CCB) : 0x31853220

State of The Call        : STATE_DEAD

TCP Sockets Used         : NO

Calling Number           : 2101

Called Number            : 745

Source IP Address (Sig  ): 192.168.0.250

Destn SIP Req Addr:Port  : 192.168.0.155:5060

Destn SIP Resp Addr:Port : 192.168.0.155:5060

Destination Name         : 192.168.0.155

Jan  9 14:47:25.030: //2469/AD3510ED82D1/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.0.250

Source IP Port    (Media): 19160

Destn  IP Address (Media):  -

Destn  IP Port    (Media): 0

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

Jan  9 14:47:25.030: //2469/AD3510ED82D1/SIP/Call/sipSPICallInfo:

Disconnect Cause (CC)    : 17

Disconnect Cause (SIP)   : 486

Jan  9 14:47:25.030: //2469/AD3510ED82D1/SIP/Info/sipSPIUdeleteccCallIdFromTable: Removing call id 9A5

Jan  9 14:47:25.034: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:

Sent:

ACK sip:745@192.168.0.155:5060 SIP/2.0

Via: SIP/2.0/UDP 192.168.0.250:5060;branch=z9hG4bK109491B

From: "GM" <2101>;tag=1647BF4-1678

To: <745>;tag=d9950e59a7eb5288i2

Date: Mon, 09 Jan 2012 14:47:25 GMT

Call-ID: ADA2EE8A-3A0711E1-82D6EEFB-5980959F@192.168.0.250

Max-Forwards: 70

CSeq: 101 ACK

Allow-Events: telephone-event

Content-Length: 0

Jan  9 14:47:26.962: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceHandleConnAgeing: Holder=0x309E1C68 Connection=0x2B2D0A48, addr=192.168.0.155, port=5060, connid=2 has been REFRESHED

Jan  9 14:47:26.962: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportSetAgeingTimer: Aging timer initiated for holder=0x309E1C68,addr=192.168.0.155

Jan  9 14:47:27.622: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDeleteContextFromTable: Context for key=[2293] removed.

Jan  9 14:47:27.622: //2467/9B5C957682CB/SIP/Info/sipSPIUdeleteCcbFromUACTable: ****Deleting from UAC table.

Jan  9 14:47:27.622: //2467/9B5C957682CB/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x3186F3D0 key=9BDAEDAC-3A0711E1-82D0EEFB-5980959F@192.168.0.250

Jan  9 14:47:27.622: //2467/9B5C957682CB/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd

Jan  9 14:47:27.622: //2467/9B5C957682CB/SIP/Info/sipSPI_ipip_free_codec_profile: Codec Profiles Freed

Jan  9 14:47:27.622: //2467/9B5C957682CB/SIP/Info/ccsip_offer_ans_delete:

Jan  9 14:47:27.622: //2467/9B5C957682CB/SIP/Info/ccsip_iwf_delete: 

Jan  9 14:47:27.622: //2467/9B5C957682CB/SIP/Info/sipSPIUfreeOneCCB: Freeing ccb 3186F3D0

Hall of Fame Super Gold

CME IOS 15 SIP trunk with SPA9000

Please read my post above and do what is asked in there.

New Member

CME IOS 15 SIP trunk with SPA9000

Hi Paolo,

Sorry for the late reply but I was sick in bed.

Kindly find below the output you requested:

Jan 27 08:43:31.840: //2583/D2EBD32596F2/SIP/Msg/ccsipDisplayMsg:

Sent:

INVITE sip:747@192.168.0.155:6060 SIP/2.0

Via: SIP/2.0/UDP 192.168.30.250:5060;branch=z9hG4bK647A8

From: "NAME" <2402>;tag=3DD0DDA4-F3D

To: <747>

Date: Fri, 27 Jan 2012 08:43:31 GMT

Call-ID: D37C7A6C-47F911E1-96F7CB10-21D3CAB4@192.168.30.250

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

Min-SE:  1800

Cisco-Guid: 3538670373-1207505377-2532494096-0567528116

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: 1327653811

Contact: <2402>

Expires: 180

Allow-Events: telephone-event

Content-Type: application/sdp

Content-Disposition: session;handling=required

Content-Length: 302

v=0

o=CiscoSystemsSIP-GW-UserAgent 3491 4172 IN IP4 192.168.30.250

s=SIP Call

c=IN IP4 192.168.30.250

t=0 0

m=audio 17540 RTP/AVP 0 100 101

c=IN IP4 192.168.30.250

a=rtpmap:0 PCMU/8000

a=rtpmap:100 X-NSE/8000

a=fmtp:100 192-194

a=rtpmap:101 telephone-event/8000

a=fmtp:101 0-16

a=ptime:20

Jan 27 08:43:31.848: //2583/D2EBD32596F2/SIP/Msg/ccsipDisplayMsg:

Received:

SIP/2.0 403 Forbidden

To: <747>;tag=60b7acd9-0

From: "NAME" <2402>;tag=3DD0DDA4-F3D

Call-ID: D37C7A6C-47F911E1-96F7CB10-21D3CAB4@192.168.30.250

CSeq: 101 INVITE

Via: SIP/2.0/UDP 192.168.30.250:5060;branch=z9hG4bK647A8;rport=57513

Timestamp: 1327653811

Server: Linksys/SPA9000-6.1.5

Allow-Events: talk, hold, conference

Content-Length: 0

Jan 27 08:43:31.852: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:

Sent:

ACK sip:747@192.168.0.155:6060 SIP/2.0

Via: SIP/2.0/UDP 192.168.30.250:5060;branch=z9hG4bK647A8

From: "NAME" <2402>;tag=3DD0DDA4-F3D

To: <747>;tag=60b7acd9-0

Date: Fri, 27 Jan 2012 08:43:31 GMT

Call-ID: D37C7A6C-47F911E1-96F7CB10-21D3CAB4@192.168.30.250

Max-Forwards: 70

CSeq: 101 ACK

Allow-Events: telephone-event

Content-Length:

New Member

CME IOS 15 SIP trunk with SPA9000

Hi Paolo,

There was a misconfiguration on the ports.

I changed the port to the defaults of 5060 and here is the new output. The error changed from forbidden to user busy

Jan 27 08:46:08.192: //2585/3012E03596F8/SIP/Msg/ccsipDisplayMsg:

Sent:

INVITE sip:747@192.168.0.155:5060 SIP/2.0

Via: SIP/2.0/UDP 192.168.30.250:5060;branch=z9hG4bK64820B

From: "NAME" <2402>;tag=3DD34060-49D

To: <747>

Date: Fri, 27 Jan 2012 08:46:08 GMT

Call-ID: 30AD4B2D-47FA11E1-96FDCB10-21D3CAB4@192.168.30.250

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

Min-SE:  1800

Cisco-Guid: 0806543413-1207570913-2532887312-0567528116

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: 1327653968

Contact: <2402>

Expires: 180

Allow-Events: telephone-event

Content-Type: application/sdp

Content-Disposition: session;handling=required

Content-Length: 300

v=0

o=CiscoSystemsSIP-GW-UserAgent 88 8727 IN IP4 192.168.30.250

s=SIP Call

c=IN IP4 192.168.30.250

t=0 0

m=audio 17634 RTP/AVP 0 100 101

c=IN IP4 192.168.30.250

a=rtpmap:0 PCMU/8000

a=rtpmap:100 X-NSE/8000

a=fmtp:100 192-194

a=rtpmap:101 telephone-event/8000

a=fmtp:101 0-16

a=ptime:20

Jan 27 08:46:08.196: //2585/3012E03596F8/SIP/Msg/ccsipDisplayMsg:

Received:

SIP/2.0 100 Trying

To: <747>

From: "NAME" <2402>;tag=3DD34060-49D

Call-ID: 30AD4B2D-47FA11E1-96FDCB10-21D3CAB4@192.168.30.250

CSeq: 101 INVITE

Via: SIP/2.0/UDP 192.168.30.250:5060;branch=z9hG4bK64820B;rport=55547

Timestamp: 1327653968

Server: Linksys/SPA9000-6.1.5

Allow-Events: talk, hold, conference

Content-Length: 0

Jan 27 08:46:08.200: //2585/3012E03596F8/SIP/Msg/ccsipDisplayMsg:

Received:

SIP/2.0 486 Busy Here

To: <747>;tag=7aeab9128827f7fi2

From: "NAME" <2402>;tag=3DD34060-49D

Call-ID: 30AD4B2D-47FA11E1-96FDCB10-21D3CAB4@192.168.30.250

CSeq: 101 INVITE

Via: SIP/2.0/UDP 192.168.30.250:5060;branch=z9hG4bK64820B;rport=55547

Timestamp: 1327653968

Server: Linksys/SPA9000-6.1.5

Allow-Events: talk, hold, conference

Content-Length: 0

Jan 27 08:46:08.204: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:

Sent:

ACK sip:747@192.168.0.155:5060 SIP/2.0

Via: SIP/2.0/UDP 192.168.30.250:5060;branch=z9hG4bK64820B

From: "NAME" <2402>;tag=3DD34060-49D

To: <747>;tag=7aeab9128827f7fi2

Date: Fri, 27 Jan 2012 08:46:08 GMT

Call-ID: 30AD4B2D-47FA11E1-96FDCB10-21D3CAB4@192.168.30.250

Max-Forwards: 70

CSeq: 101 ACK

Allow-Events: telephone-event

Content-Length: 0

New Member

CME IOS 15 SIP trunk with SPA9000

Hi Paolo,

It turns out that there is something weird in SPA functionality where it ony allows to dial the userID extension configured on the trunk (aka line number).

I was dialing another extension and it was giving the Busy here error.

I will try to search how to route many DID numbers to the SPA9000

Hall of Fame Super Gold

CME IOS 15 SIP trunk with SPA9000

From my experience, the SPA devices are of disappointng quality.

Maybe is better if you only use CME.

663
Views
0
Helpful
7
Replies
CreatePlease to create content