!!!!!!!!!!!! ! NON-WORKING configuration. After enabling the registrar, there are these messages: !!!!!!!!!!!! CMELDA001(config)#sip-ua CMELDA001(config-sip-ua)#registrar ipv4:5.39.84.82 CMELDA001(config-sip-ua)# Aug 12 12:51:09.266: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_register_reset_dns_cache: CCSIP_REGISTER:: registrar 0 DNS resolved addr reset Aug 12 12:51:09.266: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_spi_register_update_e164_registrations: CCSIP_REGISTER:: e164 number (7143167791) event (1) Aug 12 12:51:09.266: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_register_search_e164_table: ****No entry found in E164 Table Aug 12 12:51:09.266: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_spi_register_get_rcb: Getting New RCB [0x8A29D63C] Aug 12 12:51:09.266: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAddContextToTable: Added context(0x889B72B8) with key=[10] to table Aug 12 12:51:09.266: //-1/000000000000/SIP/Info/ccsip_offer_ans_init: Aug 12 12:51:09.266: //-1/000000000000/SIP/Info/ccsip_iwf_init: Aug 12 12:51:09.266: //-1/000000000000/SIP/Info/ccsip_ipip_media_service_init: Aug 12 12:51:09.266: //-1/000000000000/SIP/Info/sipSPI_ipip_vcc_Initialization: Entry... Aug 12 12:51:09.266: //-1/000000000000/SIP/Info/ccsipRegisterSetTargetInfo: p2p mode with Registrar Server = ipv4:5.39.84.82 Aug 12 12:51:09.266: //-1/000000000000/SIP/Info/ccsipRegisterSetTargetInfo: Parsing The Registrar Address Aug 12 12:51:09.266: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetOutboundHostAndDestHostPrivate: CCSIP: target_host : 5.39.84.82 target_port : 5060 Aug 12 12:51:09.266: //-1/000000000000/SIP/Info/sipSPIValidateAndCopyOutboundHost: CCSIP: copy target_host to outbound_host Aug 12 12:51:09.266: //-1/000000000000/SIP/Info/sipSPIOutboundProxyReuse: Do not reuse Outbound Proxy IP adress and Port Aug 12 12:51:09.266: //-1/000000000000/SIP/State/sipSPIChangeState: 0x889B72B8 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE) Aug 12 12:51:09.266: //-1/000000000000/SIP/Info/ccsip_spi_registrar_add_expires_header: Inside ccsip_spi_registrar_add_expires_header for Expires Aug 12 12:51:09.266: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_OUTBOUND_REGISTER Aug 12 12:51:09.266: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIIncrementOverloadCount: Local 1 Global 1 Aug 12 12:51:09.266: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_register_add_to_e164_table: ****Added to E164 Table at position: 0 Aug 12 12:51:09.266: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 40 Aug 12 12:51:09.266: //-1/000000000000/SIP/Info/act_idle_outgoing_register: In act_idle_outgoing_register Aug 12 12:51:09.266: //7/000000000000/SIP/Info/act_idle_outgoing_register: Send REGISTER to 5.39.84.82:5060 Aug 12 12:51:09.266: //7/000000000000/SIP/Info/sipSPIUaddCcbToUACTable: ****Adding to UAC table. Aug 12 12:51:09.266: //7/000000000000/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x889B72B8 key=2A8BB36F-215611E4-80148268-C3A7D889 Aug 12 12:51:09.270: //7/000000000000/SIP/Info/resolve_sig_ip_address_to_bind: signaling bind address : 10.244.3.1 Aug 12 12:51:09.270: //7/000000000000/SIP/Info/sipSPIPresendProcessing: Presend Processing called for 7 event Aug 12 12:51:09.270: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIRetrieveOutgoingPassThruData: Retrieving Data from RCB Aug 12 12:51:09.270: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIRetrieveOutgoingPassThruData: Retrieving Data from RCB Aug 12 12:51:09.270: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Converting TimeZone WAT to SIP default timezone = GMT Aug 12 12:51:09.270: //7/000000000000/SIP/Info/sipSPISendRegister: Associated container=0x88C2F23C to Register Aug 12 12:51:09.270: //7/000000000000/SIP/Transport/sipSPISendRegister: Sending REGISTER to the transport layer Aug 12 12:51:09.270: //7/000000000000/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Global configuration, Switch Transport is FALSE Aug 12 12:51:09.270: //7/000000000000/SIP/Transport/sipSPITransportSendMessage: msg=0x8A265520, addr=5.39.84.82, port=5060, sentBy_port=0, local_addr=10.244.3.1, is_req=1, transport=1, switch=0, callBack=0x814AD08C Aug 12 12:51:09.270: //7/000000000000/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Aug 12 12:51:09.270: //7/000000000000/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0 Aug 12 12:51:09.270: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportSetAgeingTimer: Aging timer initiated for holder=0x866DB658,addr=5.39.84.82 Aug 12 12:51:09.270: //-1/xxxxxxxxxxxx/SIP/Transport/sipCreateConnHolder: Created new holder=0x866DB658, addr=5.39.84.82; nailed=FALSE Aug 12 12:51:09.270: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostRequestConnection: Posting UDP conn create request for addr=5.39.84.82, port=5060, context=0x8751D4F4 Aug 12 12:51:09.270: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportSetConnWaitTimer: Wait timer set for connection=0x8751E990,addr=5.39.84.82, port=5060 Aug 12 12:51:09.270: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportSetConnWaitTimer: Wait Conn Timer started for 5000 msec Aug 12 12:51:09.270: //-1/xxxxxxxxxxxx/SIP/Transport/sipCreateConnInstance: Created new initiated conn=0x8751E990, connid=-1, addr=5.39.84.82, port=5060, local_addr=10.244.3.1, transport=UDP Aug 12 12:51:09.270: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:5.39.84.82, rport:5060 with laddr:10.244.3.1 Aug 12 12:51:09.270: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: Registering gcb=0x889B72B8 with connection=0x8751E990 Aug 12 12:51:09.270: //7/000000000000/SIP/Transport/sipSPITransportSendMessage: Deferred sending msg=0x8A265520 Aug 12 12:51:09.270: //7/000000000000/SIP/State/sipSPIChangeState: 0x889B72B8 : State change from (STATE_IDLE, SUBSTATE_NONE) to (SIP_STATE_OUTGOING_REGISTER, SUBSTATE_NONE) Aug 12 12:51:09.270: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 56 Aug 12 12:51:09.270: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWConnectionCreated: context=0x8751D4F4 Aug 12 12:51:09.270: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessConnCreated: gConnTab=0x8751D4F4, addr=5.39.84.82, port=5060, local_addr=10.244.3.1, connid=4, transport=UDP Aug 12 12:51:09.270: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessConnCreated: connection instance created for addr:5.39.84.82, port:5060 local_addr=10.244.3.1 local_port=63793 Aug 12 12:51:09.270: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportStopConnWaitTimer: Wait timer stopped for connection=0x8751E990,addr=5.39.84.82, port=5060 Aug 12 12:51:09.270: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceHandleConnectionCreated: Moving connection=0x8751E990, connid=4 state to established. local_addr=10.244.3.1, local_port=63793 Aug 12 12:51:09.270: //7/000000000000/SIP/Transport/sipTransportPostInternalMsg: Posting Internal Msg type=0 Aug 12 12:51:09.270: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 61 Aug 12 12:51:09.270: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x8A265520, addr=5.39.84.82, port=5060, local_addr=10.244.3.1, connId=4 for UDP Aug 12 12:51:09.270: //7/000000000000/SIP/State/sipSPIChangeState: 0x889B72B8 : State change from (SIP_STATE_OUTGOING_REGISTER, SUBSTATE_NONE) to (SIP_STATE_OUTGOING_REGISTER, SUBSTATE_NONE) Aug 12 12:51:09.270: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Sent: REGISTER sip:5.39.84.82:5060 SIP/2.0 Via: SIP/2.0/UDP 10.244.3.1:5060;branch=z9hG4bK513B1 From: ;tag=52B64E4-E57 To: Date: Tue, 12 Aug 2014 12:51:09 GMT Call-ID: 2A8BB36F-215611E4-80148268-C3A7D889 User-Agent: Cisco-SIPGateway/IOS-12.x Max-Forwards: 70 Timestamp: 1407847869 CSeq: 2 REGISTER Contact: Expires: 3600 Supported: path Content-Length: 0 Aug 12 12:51:09.538: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [5.39.84.82]:5060, local_address:[10.244.3.1] Aug 12 12:51:09.538: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Aug 12 12:51:09.538: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x8751D4F4 Aug 12 12:51:09.538: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessNewConnMsg: gConnTab=0x8751D4F4, addr=5.39.84.82, port=5060, local_addr=10.244.3.1, connid=4, transport=UDP Aug 12 12:51:09.538: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog Aug 12 12:51:09.538: //7/000000000000/SIP/Info/sipSPIMatchRespToReqTran: removing unneeded z9hG4bK513B1 from via branch list Aug 12 12:51:09.538: //7/000000000000/SIP/Msg/ccsipDisplayMsg: Received: SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 41.63.165.117;branch=z9hG4bK513B1;received=41.63.165.117;rport=63793 From: ;tag=52B64E4-E57 To: ;tag=as224fde17 Call-ID: 2A8BB36F-215611E4-80148268-C3A7D889 CSeq: 2 REGISTER Server: ELITEVOIP-EUROPE-01 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="sip.elitevoip.net", nonce="38a04afa" Content-Length: 0 Aug 12 12:51:09.538: //7/000000000000/SIP/Info/sipSPICheckResponseExt: non-INVITE response with no RSEQ - do not disable IS_REL1XX Aug 12 12:51:09.538: //7/000000000000/SIP/Info/sipSPIGenerateAuthorizationResponse: HA1 is: 88e9564e98e11f9323451608ac440fbe Aug 12 12:51:09.538: //7/000000000000/SIP/Info/sipSPIPresendProcessing: Presend Processing called for 7 event Aug 12 12:51:09.538: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIRetrieveOutgoingPassThruData: Retrieving Data from RCB Aug 12 12:51:09.538: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIRetrieveOutgoingPassThruData: Retrieving Data from RCB Aug 12 12:51:09.538: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Converting TimeZone WAT to SIP default timezone = GMT Aug 12 12:51:09.542: //7/000000000000/SIP/Info/sipSPISendRegister: Associated container=0x88C2F084 to Register Aug 12 12:51:09.542: //7/000000000000/SIP/Transport/sipSPISendRegister: Sending REGISTER to the transport layer Aug 12 12:51:09.542: //7/000000000000/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Global configuration, Switch Transport is FALSE Aug 12 12:51:09.542: //7/000000000000/SIP/Transport/sipSPITransportSendMessage: msg=0x8A265520, addr=5.39.84.82, port=5060, sentBy_port=0, local_addr=10.244.3.1, is_req=1, transport=1, switch=0, callBack=0x814AD08C Aug 12 12:51:09.542: //7/000000000000/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Aug 12 12:51:09.542: //7/000000000000/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0 Aug 12 12:51:09.542: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:5.39.84.82, rport:5060 with laddr:10.244.3.1 Aug 12 12:51:09.542: //7/000000000000/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x8A265520 Aug 12 12:51:09.542: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x8A265520, addr=5.39.84.82, port=5060, local_addr=10.244.3.1, connId=4 for UDP Aug 12 12:51:09.542: //7/000000000000/SIP/State/sipSPIChangeState: 0x889B72B8 : State change from (SIP_STATE_OUTGOING_REGISTER, SUBSTATE_NONE) to (SIP_STATE_OUTGOING_REGISTER, SUBSTATE_NONE) Aug 12 12:51:09.542: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Sent: REGISTER sip:5.39.84.82:5060 SIP/2.0 Via: SIP/2.0/UDP 10.244.3.1:5060;branch=z9hG4bK6A81 From: ;tag=52B64E4-E57 To: Date: Tue, 12 Aug 2014 12:51:09 GMT Call-ID: 2A8BB36F-215611E4-80148268-C3A7D889 User-Agent: Cisco-SIPGateway/IOS-12.x Max-Forwards: 70 Timestamp: 1407847869 CSeq: 3 REGISTER Contact: Expires: 3600 Authorization: Digest username="7143167791",realm="sip.elitevoip.net",uri="sip:5.39.84.82:5060",response="5c46e03a629f95c2baa2cf8316f22595",nonce="38a04afa",algorithm=MD5 Content-Length: 0 Aug 12 12:51:09.806: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [5.39.84.82]:5060, local_address:[10.244.3.1] Aug 12 12:51:09.806: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [5.39.84.82]:5060, local_address:[10.244.3.1] Aug 12 12:51:09.806: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Aug 12 12:51:09.806: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x8751D4F4 Aug 12 12:51:09.806: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessNewConnMsg: gConnTab=0x8751D4F4, addr=5.39.84.82, port=5060, local_addr=10.244.3.1, connid=4, transport=UDP Aug 12 12:51:09.806: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: OPTIONS sip:7143167791@41.63.165.117:60417 SIP/2.0 Via: SIP/2.0/UDP 5.39.84.82:5060;branch=z9hG4bK7e0701f9;rport Max-Forwards: 70 From: "asterisk" ;tag=as4bf8630c To: Contact: Call-ID: 47678e317453deee1df772272b531b21@5.39.84.82:5060 CSeq: 102 OPTIONS User-Agent: ELITEVOIP-EUROPE-01 Date: Tue, 12 Aug 2014 12:56:54 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Content-Length: 0 Aug 12 12:51:09.806: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog Aug 12 12:51:09.806: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAddContextToTable: Added context(0x889B18C8) with key=[11] to table Aug 12 12:51:09.806: //-1/000000000000/SIP/Info/ccsip_offer_ans_init: Aug 12 12:51:09.806: //-1/000000000000/SIP/Info/ccsip_iwf_init: Aug 12 12:51:09.806: //-1/000000000000/SIP/Info/ccsip_ipip_media_service_init: Aug 12 12:51:09.806: //-1/000000000000/SIP/Info/sipSPI_ipip_vcc_Initialization: Entry... Aug 12 12:51:09.806: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 5.39.84.82,Port 5060, Transport 1, SentBy Port 5060 Aug 12 12:51:09.806: //-1/000000000000/SIP/Info/resolve_sig_ip_address_to_bind: signaling bind address : 10.244.3.1 Aug 12 12:51:09.806: //-1/2ADE17D58015/SIP/State/sipSPIChangeState: 0x889B18C8 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE) Aug 12 12:51:09.810: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 5.39.84.82,Port 5060, Transport 1, SentBy Port 5060 Aug 12 12:51:09.810: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Converting TimeZone WAT to SIP default timezone = GMT Aug 12 12:51:09.810: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 5.39.84.82,Port 5060, Transport 1, SentBy Port 5060 Aug 12 12:51:09.810: //8/2ADE17D58015/SIP/Info/ccsipInitPldCallingInfo: non-numeric calling number: asterisk Aug 12 12:51:09.810: //8/2ADE17D58015/SIP/Info/sipSPIGetViaHostInURLFormat: VIA URL:sip:5.39.84.82:5060, Host:5.39.84.82 Aug 12 12:51:09.810: //8/2ADE17D58015/SIP/Info/sipSPIGetShrlPeer: Try match incoming dialpeer for Calling number: : asterisk Aug 12 12:51:09.810: //8/2ADE17D58015/SIP/Info/sipSPIGetFromCalledPartyId: P-Called-Party-ID header not found Aug 12 12:51:09.810: //8/2ADE17D58015/SIP/Info/sipSPIGetPeerByCalledPartyId: P-Called-Party-ID not found or parse error Aug 12 12:51:09.810: //8/2ADE17D58015/SIP/Info/sipSPIGetCallConfig: No match found for P-Called-Party-ID Aug 12 12:51:09.810: //8/2ADE17D58015/SIP/Info/sipSPIGetCallConfig: Precondition tag absent in Require/Supported header Aug 12 12:51:09.810: //8/2ADE17D58015/SIP/Info/sipSPIGetCallConfig: Media Antitrombone disabled Aug 12 12:51:09.810: //8/2ADE17D58015/SIP/Info/sipSPISetMediaFlowMode: Storing the configured mode as FLOW-THROUGH Aug 12 12:51:09.810: //8/2ADE17D58015/SIP/Info/sipSPISetMediaFlowMode: xcoder high-density disabled Aug 12 12:51:09.810: //8/2ADE17D58015/SIP/Info/sipSPISetMediaFlowMode: Flow Mode set to FLOW_THROUGH Aug 12 12:51:09.810: //8/2ADE17D58015/SIP/Info/sipSPIGetCallConfig: Non dial peer leg - using RTP Supported Codecs Aug 12 12:51:09.810: //8/2ADE17D58015/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 18 Aug 12 12:51:09.810: //8/2ADE17D58015/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 0 Aug 12 12:51:09.810: //8/2ADE17D58015/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 8 Aug 12 12:51:09.810: //8/2ADE17D58015/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 9 Aug 12 12:51:09.810: //8/2ADE17D58015/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 4 Aug 12 12:51:09.810: //8/2ADE17D58015/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 2 Aug 12 12:51:09.810: //8/2ADE17D58015/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 15 Aug 12 12:51:09.810: //8/2ADE17D58015/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 3 Aug 12 12:51:09.810: //8/2ADE17D58015/SIP/Info/sipSPIGetModemInfoPerCall: peer_callID=0 Aug 12 12:51:09.810: //8/2ADE17D58015/SIP/Info/sipSPISetOverlapConfiguration: Overlap signaling: FALSE: Endpt: SIP Trunk Aug 12 12:51:09.810: //8/2ADE17D58015/SIP/Info/sipSPI_ipip_GetHdrPassthruCfg: Hdr passthrough config:1 tag:0 Aug 12 12:51:09.810: //8/2ADE17D58015/SIP/Info/sipSPI_ipip_GetCopyListCfg: Copy-list config:2 tag:0 Aug 12 12:51:09.810: //8/2ADE17D58015/SIP/Info/sipSPI_ipip_build_consolidated_header_list: Both passthru and copylist are disabled Aug 12 12:51:09.810: //8/2ADE17D58015/SIP/Info/sipSPIValidateStreamAddrType: stream:1, Mode : 1 Aug 12 12:51:09.810: //8/2ADE17D58015/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 10.244.3.1 Aug 12 12:51:09.810: //8/2ADE17D58015/SIP/Info/resolve_sig_ip_address_to_bind: signaling bind address : 10.244.3.1 Aug 12 12:51:09.814: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_OPTIONS_RESP Aug 12 12:51:09.814: //8/2ADE17D58015/SIP/Info/sact_idle_new_message_options: ccsip_api_options_ind returned: SIP_SUCCESS Aug 12 12:51:09.814: //8/2ADE17D58015/SIP/State/sipSPIChangeState: 0x889B18C8 : State change from (STATE_IDLE, SUBSTATE_NONE) to (SIP_STATE_OPTIONS_WAIT, SUBSTATE_NONE) Aug 12 12:51:09.814: //8/2ADE17D58015/SIP/Info/sipSPIUaddCcbToUASReqTable: ****Adding to UAS Request table. Aug 12 12:51:09.814: //8/2ADE17D58015/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x889B18C8 key=47678e317453deee1df772272b531b21@5.39.84.82:50607143167791 Aug 12 12:51:09.814: //8/2ADE17D58015/SIP/Info/sipSPIUaddccCallIdToTable: Adding call id 8 to table Aug 12 12:51:09.814: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Aug 12 12:51:09.814: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x8751D4F4 Aug 12 12:51:09.814: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessNewConnMsg: gConnTab=0x8751D4F4, addr=5.39.84.82, port=5060, local_addr=10.244.3.1, connid=4, transport=UDP Aug 12 12:51:09.814: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog Aug 12 12:51:09.814: //7/000000000000/SIP/Info/sipSPIMatchRespToReqTran: removing unneeded z9hG4bK6A81 from via branch list Aug 12 12:51:09.814: //7/000000000000/SIP/Msg/ccsipDisplayMsg: Received: SIP/2.0 200 OK Via: SIP/2.0/UDP 41.63.165.117;branch=z9hG4bK6A81;received=41.63.165.117;rport=63793 From: ;tag=52B64E4-E57 To: ;tag=as224fde17 Call-ID: 2A8BB36F-215611E4-80148268-C3A7D889 CSeq: 3 REGISTER Server: ELITEVOIP-EUROPE-01 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Expires: 3600 Contact: ;expires=3600 Date: Tue, 12 Aug 2014 12:56:54 GMT Content-Length: 0 Aug 12 12:51:09.814: //7/000000000000/SIP/Info/sipSPICheckResponseExt: non-INVITE response with no RSEQ - do not disable IS_REL1XX Aug 12 12:51:09.814: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDecrementOverloadCount: Count:Local 0 Global 0 Aug 12 12:51:09.814: //7/000000000000/SIP/Info/sipSPIRegPthruProcessResponse: Processing response w/ resp code == 200 Aug 12 12:51:09.814: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetRPCBFromRCB: Retreiving RCB [0x8A29D63C] from RPCB [0x0] Aug 12 12:51:09.814: //7/000000000000/SIP/Error/sipSPIRegPthruProcessResponse: Error NO RPCB Aug 12 12:51:09.814: //-1/xxxxxxxxxxxx/SIP/Info/ccsipRegisterStartRCBTimer: Starting timer for pattern 7143167791 for 2880 seconds Aug 12 12:51:09.814: //7/000000000000/SIP/Info/ccsip_gw_register_process_response: No P-Assoicated-URI present in Register Response Aug 12 12:51:09.814: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDeleteContextFromTable: Context for key=[10] removed. Aug 12 12:51:09.814: //7/000000000000/SIP/Info/sipSPIUdeleteCcbFromUACTable: ****Deleting from UAC table. Aug 12 12:51:09.814: //7/000000000000/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x889B72B8 key=2A8BB36F-215611E4-80148268-C3A7D889 Aug 12 12:51:09.814: //7/000000000000/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd Aug 12 12:51:09.814: //7/000000000000/SIP/Info/sipSPI_ipip_free_codec_profile: Codec Profiles Freed Aug 12 12:51:09.814: //7/000000000000/SIP/Info/ccsip_offer_ans_delete: Aug 12 12:51:09.814: //7/000000000000/SIP/Info/ccsip_iwf_delete: Aug 12 12:51:09.814: //7/000000000000/SIP/Info/sipSPIUfreeOneCCB: Freeing ccb 889B72B8 Aug 12 12:51:09.814: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContextFromTable: NO context for key[10] Aug 12 12:51:09.814: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 38 Aug 12 12:51:09.818: //8/2ADE17D58015/SIP/Info/sipSPISendOptionsResponse: Associated container=0x88C2EE74 to Options Response Aug 12 12:51:09.818: //8/2ADE17D58015/SIP/Transport/sipSPITransportSendMessage: msg=0x88C8167C, addr=5.39.84.82, port=5060, sentBy_port=5060, local_addr=10.244.3.1, is_req=0, transport=1, switch=0, callBack=0x814AD178 Aug 12 12:51:09.818: //8/2ADE17D58015/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Aug 12 12:51:09.818: //8/2ADE17D58015/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0 Aug 12 12:51:09.818: //8/2ADE17D58015/SIP/Transport/sipTransportLogicSendMsg: Trying to send resp=0x88C8167C to default port=5060 Aug 12 12:51:09.818: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:5.39.84.82, rport:5060 with laddr:10.244.3.1 Aug 12 12:51:09.818: //8/2ADE17D58015/SIP/Transport/sipTransportLogicSendMsg: Connection obtained...sending msg=0x88C8167C Aug 12 12:51:09.818: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x88C8167C, addr=5.39.84.82, port=5060, local_addr=10.244.3.1, connId=4 for UDP Aug 12 12:51:09.818: //8/2ADE17D58015/SIP/Msg/ccsipDisplayMsg: Sent: SIP/2.0 200 OK Via: SIP/2.0/UDP 5.39.84.82:5060;branch=z9hG4bK7e0701f9;rport From: "asterisk" ;tag=as4bf8630c To: ;tag=52B6700-B03 Date: Tue, 12 Aug 2014 12:51:09 GMT Call-ID: 47678e317453deee1df772272b531b21@5.39.84.82:5060 Server: Cisco-SIPGateway/IOS-12.x CSeq: 102 OPTIONS Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER Allow-Events: telephone-event Accept: application/sdp Supported: 100rel,timer,resource-priority,replaces,sdp-anat Content-Type: application/sdp Content-Length: 163 v=0 o=CiscoSystemsSIP-GW-UserAgent 1585 4431 IN IP4 10.244.3.1 s=SIP Call c=IN IP4 10.244.3.1 t=0 0 m=audio 0 RTP/AVP 18 0 8 9 4 2 15 3 c=IN IP4 10.244.3.1 !!!!!!!!!!!! ! I Can see the sucessful registration on sip-ua !!!!!!!!!!!! CMELDA001(config-sip-ua)# CMELDA001(config-sip-ua)#end CMELDA001#sh ip-ua re Aug 12 12:51:34.686: %SYS-5-CONFIG_I: Configured from console by supmultirede on vty0 (10 CMELDA001# CMELDA001#sh sip-ua Aug 12 12:51:41.818: //8/2ADE17D58015/SIP/Info/sipSPIUdeleteccCallIdFromTable: Removing call id 8 Aug 12 12:51:41.818: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDeleteContextFromTable: Context for key=[11] removed. Aug 12 12:51:41.818: //8/2ADE17D58015/SIP/Info/sipSPIUdeleteCcbFromUASReqTable: ****Deleting from UAS Request table. Aug 12 12:51:41.818: //8/2ADE17D58015/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x889B18C8 key=47678e317453deee1df772272b531b21@5.39.84.82:50607143167791 Aug 12 12:51:41.818: //8/2ADE17D58015/SIP/Info/sipSPIUdeleteCcbFromUASRespTable: ****Deleting from UAS Response table. regist Aug 12 12:51:41.818: //8/2ADE17D58015/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd Aug 12 12:51:41.818: //8/2ADE17D58015/SIP/Info/sipSPI_ipip_free_codec_profile: Codec Profiles Freed Aug 12 12:51:41.818: //8/2ADE17D58015/SIP/Info/ccsip_offer_ans_delete: Aug 12 12:51:41.818: //8/2ADE17D58015/SIP/Info/ccsip_iwf_delete: Aug 12 12:51:41.818: //8/2ADE17D58015/SIP/Info/sipSPIUfreeOneCCB: Free CMELDA001# CMELDA001# CMELDA001# CMELDA001#sh sip-ua register status Line peer expires(sec) registered P-Associ-URI ================================ ========== ============ ========== ============ 7143167791 -1 2834 yes CMELDA001# CMELDA001# !!!!!!!!!!!! ! This happens when I send a call from the PBX: !!!!!!!!!!!! Aug 12 12:51:56.470: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceHandleConnAgeing: Holder=0x8A18C8B8 Connection=0x8751E8AC, addr=10.30.0.2, port=5060, connid=3 has been REFRESHED Aug 12 12:51:56.470: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportSetAgeingTimer: Aging timer initiated for holder=0x8A18C8B8,addr=10.30.0.2 CMELDA001# Aug 12 12:52:05.830: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [10.30.0.2]:5060, local_address:[10.244.3.1] Aug 12 12:52:05.830: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Aug 12 12:52:05.830: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0 Aug 12 12:52:05.830: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: INVITE sip:103@10.244.3.1;user=phone;transport=udp SIP/2.0 Via: SIP/2.0/UDP 10.30.0.2:5060;branch=z9hG4bK-d8754z-d8c489750d22503d-1---d8754z-;rport Max-Forwards: 70 Contact: To: From: "TESTE ANGOLA";tag=1f30f315 Call-ID: NjgyZTFkNzRkYWI4ZjBkZWVkODQ4MmFmMTQ4NGRmNWQ. CSeq: 1 INVITE Session-Expires: 1800 Min-SE: 90 Allow: INVITE, OPTIONS, BYE, ACK, CANCEL, INFO, REGISTER, REFER, PRACK, SUBSCRIBE, NOTIFY, MESSAGE, UPDATE Content-Type: application/sdp Supported: timer, 100rel User-Agent: Aastra MX-ONE SN/13.211.3 Privacy: none Content-Length: 575 v=0 o=0040010001 6046662273086180241 6046662277380516703 IN IP4 10.30.0.7 s=MX-ONE c=IN IP4 10.30.0.7 t=0 0 m=audio 39572 RTP/AVP 8 0 18 4 101 13 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=rtpmap:4 G723/8000 a=rtpmap:101 telephone-event/8000 a=rtpmap:13 CN/8000 a=ptime:30 a=sqn:0 a=cdsc:1 image udptl t38 a=cpar:a=T38FaxVersion:0 a=cpar:a=T38MaxBitRate:14400 a=cpar:a=T38FaxRateManagement:transferredTCF a=cpar:a=T38FaxMaxBuffer:9772 a=cpar:a=T38FaxMaxDatagram:1472 a=cpar:a=T38FaxUdpEC:t38UDPRedundancy a=silenceSupp:on - - - - Aug 12 12:52:05.830: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog Aug 12 12:52:05.830: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAddContextToTable: Added context(0x889B18C8) with key=[12] to table Aug 12 12:52:05.830: //-1/000000000000/SIP/Info/ccsip_offer_ans_init: Aug 12 12:52:05.830: //-1/000000000000/SIP/Info/ccsip_iwf_init: Aug 12 12:52:05.830: //-1/000000000000/SIP/Info/ccsip_ipip_media_service_init: Aug 12 12:52:05.834: //-1/000000000000/SIP/Info/sipSPI_ipip_vcc_Initialization: Entry... Aug 12 12:52:05.834: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 10.30.0.2,Port 5060, Transport 1, SentBy Port 5060 Aug 12 12:52:05.834: //-1/000000000000/SIP/Info/resolve_sig_ip_address_to_bind: signaling bind address : 10.244.3.1 Aug 12 12:52:05.834: //-1/4C4349858016/SIP/State/sipSPIChangeState: 0x889B18C8 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE) Aug 12 12:52:05.834: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 10.30.0.2,Port 5060, Transport 1, SentBy Port 5060 Aug 12 12:52:05.834: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Converting TimeZone WAT to SIP default timezone = GMT Aug 12 12:52:05.834: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 10.30.0.2,Port 5060, Transport 1, SentBy Port 5060 Aug 12 12:52:05.834: //-1/4C4349858016/SIP/Info/resolve_sig_ip_address_to_bind: signaling bind address : 10.244.3.1 Aug 12 12:52:05.834: //-1/4C4349858016/SIP/Info/sipSPICheckAssertedIdConfig: Dialpeer match is not yet done Aug 12 12:52:05.834: //-1/4C4349858016/SIP/Info/sipSPICheckAssertedIdConfig: Dialpeer match is not yet done Aug 12 12:52:05.834: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetPrivacy: No valid Privacy found Aug 12 12:52:05.834: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentGTD: No GTD found in inbound container Aug 12 12:52:05.834: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentCSTA: No CSTA found in inbound container Aug 12 12:52:05.834: //-1/4C4349858016/SIP/Info/sipSPIUaddCcbToUASReqTable: ****Adding to UAS Request table. Aug 12 12:52:05.834: //-1/4C4349858016/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x889B18C8 key=NjgyZTFkNzRkYWI4ZjBkZWVkODQ4MmFmMTQ4NGRmNWQ.103 Aug 12 12:52:05.834: //-1/4C4349858016/SIP/Info/sipSPIMatchSrcIpGroup: Match not found on carrier id Aug 12 12:52:05.834: //-1/4C4349858016/SIP/Info/sipSPIMatchSrcIpGroup: Match not found on Incoming called number: 103 Aug 12 12:52:05.834: //-1/4C4349858016/SIP/Info/sipSPIMatchSrcIpGroup: Match not found on destination pattern: 726 Aug 12 12:52:05.834: //-1/4C4349858016/SIP/Info/ccsipUpdateIncomingCallParams: ccCallInfo: Calling name TESTE ANGOLA, number 726, Calling oct3 0x00, oct_3a 0x80, Called number 103 Aug 12 12:52:05.834: //-1/4C4349858016/SIP/Info/sipSPIGetViaHostInURLFormat: VIA URL:sip:10.30.0.2:5060, Host:10.30.0.2 Aug 12 12:52:05.838: //-1/4C4349858016/SIP/Info/sipSPIGetShrlPeer: Try match incoming dialpeer for Calling number: : 726 Aug 12 12:52:05.838: //-1/4C4349858016/SIP/Info/sipSPIGetFromCalledPartyId: P-Called-Party-ID header not found Aug 12 12:52:05.838: //-1/4C4349858016/SIP/Info/sipSPIGetPeerByCalledPartyId: P-Called-Party-ID not found or parse error Aug 12 12:52:05.838: //-1/4C4349858016/SIP/Info/sipSPIGetCallConfig: No match found for P-Called-Party-ID Aug 12 12:52:05.838: //-1/4C4349858016/SIP/Info/sipSPIGetCallConfig: Peer tag 1 matched for incoming call Aug 12 12:52:05.838: //-1/4C4349858016/SIP/Info/sipSPIGetCallConfig: Precondition tag absent in Require/Supported header Aug 12 12:52:05.838: //-1/4C4349858016/SIP/Info/resolve_sig_ip_address_to_bind: signaling bind address : 10.244.3.1 Aug 12 12:52:05.838: //-1/4C4349858016/SIP/Info/sipSPIGetCallConfig: Precondition tag absent in Require/Supported header Aug 12 12:52:05.838: //-1/4C4349858016/SIP/Info/sipSPIGetCallConfig: Media Antitrombone disabled Aug 12 12:52:05.838: //-1/4C4349858016/SIP/Info/sipSPISetMediaFlowMode: Storing the configured mode as FLOW-THROUGH Aug 12 12:52:05.838: //-1/4C4349858016/SIP/Info/sipSPISetMediaFlowMode: xcoder high-density disabled Aug 12 12:52:05.838: //-1/4C4349858016/SIP/Info/sipSPISetMediaFlowMode: Flow Mode set to FLOW_THROUGH Aug 12 12:52:05.838: //-1/4C4349858016/SIP/Info/sipSPIGetCallConfig: Using Voice Class Codec, tag = 1 and offer-all is = FALSE Aug 12 12:52:05.838: //-1/4C4349858016/SIP/Media/sipSPICopyStunConfigFromPeerToCCB: Firewall traversal is not enabled Aug 12 12:52:05.838: //-1/4C4349858016/SIP/Info/sipSPIGetModemInfoPerCall: peer_callID=0 Aug 12 12:52:05.838: //-1/4C4349858016/SIP/Info/sipSPIGetCallConfig: Media forking disabled Aug 12 12:52:05.838: //-1/4C4349858016/SIP/Info/sipSPISetOverlapConfiguration: Overlap signaling: FALSE: Endpt: SIP Trunk Aug 12 12:52:05.838: //-1/4C4349858016/SIP/Info/sipSPI_ipip_GetHdrPassthruCfg: Hdr passthrough config:1 tag:0 Aug 12 12:52:05.838: //-1/4C4349858016/SIP/Info/sipSPI_ipip_GetCopyListCfg: Copy-list config:2 tag:0 Aug 12 12:52:05.838: //-1/4C4349858016/SIP/Info/sipSPI_ipip_build_consolidated_header_list: Both passthru and copylist are disabled Aug 12 12:52:05.838: //-1/4C4349858016/SIP/Info/sipSPIContinueNewMsgInvite: Calling name TESTE ANGOLA, number 726, Calling oct3 0x00, oct_3a 0x80, ext_priv 0x00, Called number 103, oct3 0x00 Aug 12 12:52:05.838: //-1/4C4349858016/SIP/Info/sipSPIContinueNewMsgInvite: Carrier id code , prev_cid NONE, next_cid NONE, prev_tgrp NONE, next_tgrp NONE Aug 12 12:52:05.838: //-1/4C4349858016/SIP/Info/sipSPIContinueNewMsgInvite: Requires reliable-provisional support Aug 12 12:52:05.838: //-1/4C4349858016/SIP/Info/sipSPIValidateRequestUri: Not Enabled Aug 12 12:52:05.838: //-1/4C4349858016/SIP/Info/sipSPIRscmsmAvail: Value returned by check is = 0 Aug 12 12:52:05.838: //9/4C4349858016/SIP/Info/sipSPI_ipip_IsSDPPassthruEnabled: - 0 Aug 12 12:52:05.838: //9/4C4349858016/SIP/Event/Session-Timer/sipSTSLMain: Event: E_STSL_SESSION_REFRESH_REQ Aug 12 12:52:05.838: //9/4C4349858016/SIP/Event/Session-Timer/sipSTSLMain: dir:2, method:102, resp_code:0, container:88C2EE1C Aug 12 12:52:05.838: //9/4C4349858016/SIP/Info/Session-Timer/sipSTSLExtractSessionExpiresHdr: Session-Expires value: 1800 refresher: none Aug 12 12:52:05.838: //9/4C4349858016/SIP/Info/Session-Timer/sipSTSLExtractMinSEHdr: Min-SE Duration: 90 Aug 12 12:52:05.838: //9/4C4349858016/SIP/Info/Session-Timer/sipSTSLGetInternalSREvent: E_STSL_INITIAL_SR_REQ Aug 12 12:52:05.838: //9/4C4349858016/SIP/Info/Session-Timer/sipSTSLInitialSRReqPeerEventGen: sending received session expires to the peer leg Aug 12 12:52:05.838: //9/4C4349858016/SIP/Event/Session-Timer/sipSTSLPrintTDContainer: Peer-Event: E_STSL_PASS_ST_PARAMS, SE Value:1800, SE Refresher:none, Min-SE Value:1800, flags:2001 Aug 12 12:52:05.838: //9/4C4349858016/SIP/Info/Session-Timer/sipSTSLMain: SE: 1800;refresher:none peer refresher:none, flags:2001, posted event:E_STSL_INVALID_PEER_EVENT, reason:4 Configured SE:1800, Configured Min-SE:1800 Aug 12 12:52:05.838: //9/4C4349858016/SIP/Info/sipSPIProcessHistoryInfoHeader: No HI headers recvd from app container Aug 12 12:52:05.838: //9/4C4349858016/SIP/Info/sipSPIProcessDiversionHeader: No diversion headers recvd from app container Aug 12 12:52:05.838: //9/4C4349858016/SIP/Info/sipSPIProcessReplacesHeader: No replaces hdr found Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/sipSPIDoMediaNegotiation: Number of m-lines = 1 Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/sipSPIValidateConnectionAddress: Dest port = 39572 SIP: (9) Attribute mid, level 1 instance 1 not found. Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/sipSPIValidateStreamAddrType: stream:1, Mode : 1 Aug 12 12:52:05.842: //9/4C4349858016/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 10.244.3.1 Aug 12 12:52:05.842: //-1/xxxxxxxxxxxx/SIP/Info/sipSPICheckDynPayloadUse: Dynamic payload(101) reserved for codec No Codec Aug 12 12:52:05.842: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIUpdateDynamicPayloadunused: Unreserving dynamic payload type 96 Aug 12 12:52:05.842: //-1/xxxxxxxxxxxx/SIP/Info/sipSPICheckDynPayloadUse: Dynamic payload(101) could not be reserved as its in use by other codec No Codec Aug 12 12:52:05.842: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIUpdateDynamicPT: Requested payload-Type (101) is reserved by another application Aug 12 12:52:05.842: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIUpdateDynamicPayloadunused: Unreserving dynamic payload type 98 Aug 12 12:52:05.842: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIUpdateDynamicPayloadunused: Unreserving dynamic payload type 101 Aug 12 12:52:05.842: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAllocateFreeDynamicPT: Allocating free Dynamic Payload : 98 for Codec: Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/sipSPIDoAudioNegotiation: Codec (g711ulaw) Negotiation Successful on Static Payload for m-line 1 Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/sipSPIDoPtimeNegotiation: One ptime attribute found - value:30 Aug 12 12:52:05.842: //-1/xxxxxxxxxxxx/SIP/Info/convert_ptime_to_codec_bytes: Values :Codec: g711ulaw ptime :30, codecbytes: 240 Aug 12 12:52:05.842: //-1/xxxxxxxxxxxx/SIP/Info/convert_codec_bytes_to_ptime: Values :Codec: g711ulaw codecbytes :160, ptime: 20 Aug 12 12:52:05.842: //9/4C4349858016/SIP/Media/sipSPIDoPtimeNegotiation: Offered ptime:30, Negotiated ptime:20 Negotiated codec bytes: 160 for codec g711ulaw Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/sipSPISetFaxFlags: FAX_PASSTHROUGH = 0, END_FAX_PASSTHROUGH = 0 Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/sipSPIDoDTMFRelayNegotiation: m-line index 1 Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/sipSPIDoDTMFRelayNegotiation: Requested DTMF-RELAY option(s) not found in Preferred DTMF-RELAY option list! Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/sipSPIStreamTypeAndDtmfRelay: DTMF Relay mode: Inband Voice Aug 12 12:52:05.842: //-1/xxxxxxxxxxxx/SIP/Info/sip_sdp_get_modem_relay_cap_params: V150 NSE payload = 0, SSE payload = 0, SPRT payload=0 Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/sip_select_modem_relay_params: X-tmr not present in SDP. Disable modem relay Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/sipSPIGetSDPDirectionAttribute: No direction attribute present or multiple direction attributes that can't be handled for m-line:1 and num-a-lines:0 Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/sipSPIDoAudioNegotiation: Codec negotiation successful for media line 1 payload_type=0, codec_bytes=160, codec=g711ulaw, dtmf_relay=inband-voice stream_type=voice-only (0), dest_ip_address=10.30.0.7, dest_port=39572 Aug 12 12:52:05.842: //9/4C4349858016/SIP/State/sipSPIChangeStreamState: Stream (callid = -1) State changed from (STREAM_DEAD) to (STREAM_ADDING) Aug 12 12:52:05.842: //9/4C4349858016/SIP/Media/sipSPIUpdCallWithSdpInfo: Preferred Codec : g711ulaw, bytes :160 Preferred DTMF relay : inband-voice Preferred NTE payload : 98 Early Media : No Delayed Media : No Bridge Done : No New Media : No DSP DNLD Reqd : No Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/sipSPIValidateStreamAddrType: stream:1, Mode : 1 Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/resolve_media_ip_address_to_bind: Media already bound, use existing source_media_ip_addr Aug 12 12:52:05.842: //9/4C4349858016/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 10.244.3.1 Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/ccsip_offer_ans_handle_rcvd_sdp: Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/ccsip_offer_ans_process_event: Aug 12 12:52:05.842: //9/4C4349858016/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_RCVD Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/ccsip_offer_ans_is_invite_offer_valid: - 1 Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/ccsip_offer_ans_common_offer_rcvd_hdlr: Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/ccsip_iwf_handle_network_event: Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/ccsip_iwf_process_event: Aug 12 12:52:05.842: //9/4C4349858016/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_RCVD_SDP Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/sip_iwf_def_ed_rcvd_sdp_hdlr: Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: CallID 9, sdp 0x866D7E10 channels 0x889B2F1C Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/copy_channels: callId 9 size 0 ptr 0x8A1B6D6C) Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: stream_callid = 9, peer_stream_callid = -1 Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: Hndl ptype 8 mline 1 Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: Selecting codec g711alaw Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/codec_found: Codec to be matched: 6 Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/codec_found: No match for the codecs found.. Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: Hndl ptype 0 mline 1 Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: Selecting codec g711ulaw Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/codec_found: Codec to be matched: 5 Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/codec_found: codecs[i] = 5 & codec = 5 are same.. Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: ADD AUDIO CODEC 5 Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/sipSPI_ipip_update_codec_params_in_channelInfo: Aug 12 12:52:05.842: //-1/xxxxxxxxxxxx/SIP/Info/convert_codec_bytes_to_ptime: Values :Codec: g711ulaw codecbytes :160, ptime: 20 Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/sipSPI_ipip_update_codec_params_in_channelInfo: Adding negotiated codec 5 ptype 0 time 20, bytes 160 as channel 0 mline 1 ss 1 10.30.0.7:39572 Aug 12 12:52:05.842: //9/4C4349858016/SIP/Error/sipSPI_ipip_update_codec_params_in_channelInfo: failed to update call entry Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: Media negotiation done: stream->negotiated_ptime=20,stream->negotiated_codec_bytes=160,stream->mline_index=1, media_ndx=1 Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: Hndl ptype 18 mline 1 Aug 12 12:52:05.842: //9/4C4349858016/SIP/Media/sipSPISelectCodecVersion: Codec (g729br8) is not in preferred list Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/sipSPI_ipip_update_static_codec_params: An exact codec match not configured, using interoperable codec g729r8 Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: Selecting codec g729r8 Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/codec_found: Codec to be matched: 16 Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/codec_found: codecs[i] = 16 & codec = 16 are same.. Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: ADD AUDIO CODEC 16 Aug 12 12:52:05.842: //9/4C4349858016/SIP/Info/sipSPI_ipip_update_codec_params_in_channelInfo: Aug 12 12:52:05.846: //9/4C4349858016/SIP/Info/sipSPI_ipip_GetCodecBytePtimeFromSdp: Aug 12 12:52:05.846: //-1/xxxxxxxxxxxx/SIP/Info/convert_ptime_to_codec_bytes: Values :Codec: g729r8 ptime :30, codecbytes: 30 Aug 12 12:52:05.846: //9/4C4349858016/SIP/Info/sipSPI_ipip_update_codec_params_in_channelInfo: Adding negotiated codec 16 ptype 18 time 30, bytes 20 as channel 1 mline 1 ss 1 10.30.0.7:39572 Aug 12 12:52:05.846: //9/4C4349858016/SIP/Error/sipSPI_ipip_update_codec_params_in_channelInfo: failed to update call entry Aug 12 12:52:05.846: //9/4C4349858016/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: Hndl ptype 4 mline 1 Aug 12 12:52:05.846: //9/4C4349858016/SIP/Media/sipSPISelectCodecVersion: Codec (No Codec ) is not in preferred list Aug 12 12:52:05.846: //9/4C4349858016/SIP/Info/sipSPI_ipip_update_static_codec_params: An exact codec match not configured, using interoperable codec g729r8 pre-ietf Aug 12 12:52:05.846: //9/4C4349858016/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: Selecting codec g729r8 pre-ietf Aug 12 12:52:05.846: //9/4C4349858016/SIP/Info/codec_found: Codec to be matched: 0 Aug 12 12:52:05.846: //9/4C4349858016/SIP/Info/codec_found: codecs[i] = 16 & codec = 0 are same.. Aug 12 12:52:05.846: //9/4C4349858016/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: ADD AUDIO CODEC 0 Aug 12 12:52:05.846: //9/4C4349858016/SIP/Info/sipSPI_ipip_update_codec_params_in_channelInfo: Aug 12 12:52:05.846: //9/4C4349858016/SIP/Info/sipSPI_ipip_GetCodecBytePtimeFromSdp: Aug 12 12:52:05.846: //-1/xxxxxxxxxxxx/SIP/Info/convert_ptime_to_codec_bytes: Values :Codec: g729r8 pre-ietf ptime :30, codecbytes: 30 Aug 12 12:52:05.846: //9/4C4349858016/SIP/Info/sipSPI_ipip_update_codec_params_in_channelInfo: Adding negotiated codec 0 ptype 4 time 30, bytes 30 as channel 2 mline 1 ss 1 10.30.0.7:39572 Aug 12 12:52:05.846: //9/4C4349858016/SIP/Error/sipSPI_ipip_update_codec_params_in_channelInfo: failed to update call entry Aug 12 12:52:05.846: //9/4C4349858016/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: Hndl ptype 101 mline 1 Aug 12 12:52:05.846: //9/4C4349858016/SIP/Info/sipSPI_ipip_update_dynamic_codec_params: Aug 12 12:52:05.846: //9/4C4349858016/SIP/Info/sipSPI_ipip_upd_2833_dtmf_params: Aug 12 12:52:05.846: //9/4C4349858016/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: Hndl ptype 13 mline 1 Aug 12 12:52:05.846: //9/4C4349858016/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: Selecting codec No Codec Aug 12 12:52:05.846: //9/4C4349858016/SIP/Error/sipSPI_ipip_update_call_entry: failed to update call entry Aug 12 12:52:05.846: //9/4C4349858016/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: Copy sdp to channel- AFTER CODEC FILTERING: ccb->pld.ipip_caps.codecInfo[0].codec = 5 Aug 12 12:52:05.846: //9/4C4349858016/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: Copy sdp to channel- AFTER CODEC FILTERING: ccb->pld.ipip_caps.codecInfo[1].codec = 16 Aug 12 12:52:05.846: //9/4C4349858016/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: Copy sdp to channel- AFTER CODEC FILTERING: ccb->pld.ipip_caps.codecInfo[2].codec = 0 Aug 12 12:52:05.846: //9/4C4349858016/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: Copy sdp to channel- AFTER CODEC FILTERING: ccb->pld.ipip_caps.codecInfo[3].codec = -1 Aug 12 12:52:05.846: //9/4C4349858016/SIP/Info/sip_iwf_sip_copy_sdp_to_channelInfo: srcChannelID = -1, dstChannelID = 9 Aug 12 12:52:05.846: //9/4C4349858016/SIP/Media/sipSPIDisplayStreamInfo: Stream type : voice-only Media line : 1 State : STREAM_ADDING (2) Stream address type : 1 Callid : 9 Peer Callid : -1 RTP/SRTP Negotiated : 8 Negotiated Codec : g711ulaw, bytes :160 Nego. Codec payload : 0 (tx), 0 (rx) Negotiated DTMF relay : inband-voice Negotiated NTE payload : 0 (tx), 0 (rx) Negotiated CN payload : 13 Media Srce Addr/Port : [10.244.3.1]:0 Media Dest Addr/Port : [10.30.0.7]:39572 Aug 12 12:52:05.846: //9/4C4349858016/SIP/Info/sipSPI_ipip_calculate_channel_count: Number of streams to report = 1 Aug 12 12:52:05.846: //-1/xxxxxxxxxxxx/SIP/Error/sipSPI_ipip_set_channel_count: Unable to set CHANNEL_COUNT for callid 9 Aug 12 12:52:05.846: //9/4C4349858016/SIP/Error/sip_iwf_sip_copy_sdp_to_channelInfo: Channel count is not set at this point. Not SIP-SIP or SET_MODE is not done. Aug 12 12:52:05.846: //9/4C4349858016/SIP/State/ccsip_cnfsm_debugs: IWF:next_state:S_SIP_IWF_SDP_RCVD_AWAIT_PEER_EVENT Aug 12 12:52:05.846: //9/4C4349858016/SIP/State/ccsip_cnfsm_debugs: OA:next_state:S_SIP_EARLY_DIALOG_OFFER_RCVD Aug 12 12:52:05.846: //9/4C4349858016/SIP/Media/sipSPIUpdCallWithSdpInfo: Stream type : voice-only Media line : 1 State : STREAM_ADDING (2) Stream address type : 1 Callid : 9 Negotiated Codec : g711ulaw, bytes :160 Nego. Codec payload : 0 (tx), 0 (rx) Negotiated DTMF relay : inband-voice Negotiated NTE payload : 0 (tx), 0 (rx) Negotiated CN payload : 13 Media Srce Addr/Port : [10.244.3.1]:0 Media Dest Addr/Port : [10.30.0.7]:39572 Aug 12 12:52:05.846: //9/4C4349858016/SIP/Info/sipSPIHandleInviteMedia: Negotiated Codec : g711ulaw, bytes :160 Preferred Codec : g711ulaw, bytes :160 Preferred DTMF relay 1 : 0 Preferred DTMF relay 2 : 0 Negotiated DTMF relay : 0 Preferred and Negotiated NTE payloads: 98 0 Preferred and Negotiated NSE payloads: 100 0 Preferred and Negotiated Modem Relay: 0 0 Preferred and Negotiated V150.1 Modem Passthrough: 0 0 Preferred and Negotiated V150.1 Modem Relay: 0 0 Preferred and Negotiated Modem Relay GwXid: 1 0 Aug 12 12:52:05.846: //9/4C4349858016/SIP/Info/sipSPIDoQoSNegotiationWithMediaLine: QOS negotiation for mline_index 1 Aug 12 12:52:05.846: //9/4C4349858016/SIP/Info/sipSPIDoStreamQoSNegotiation: Best effort Aug 12 12:52:05.846: //9/4C4349858016/SIP/Info/sipSPICanSetFallbackFlag: Local Fallback is not active Aug 12 12:52:05.846: //-1/xxxxxxxxxxxx/SIP/Media/sipSPIReserveRtpPort: reserved port 17758 for stream 1 Aug 12 12:52:05.846: //9/4C4349858016/SIP/Info/sipSPIUpdateSrcSdpFixedPart: Reserving rtp port for stream 1, src_port=17758 Aug 12 12:52:05.846: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetMediaDirectionForStream: Setting Media direction SENDRECV for stream 1 Aug 12 12:52:05.846: //9/4C4349858016/SIP/Info/sipSPIUpdateSrcSdpVariablePart: Setting stream 1 portnum to 17758 Aug 12 12:52:05.846: //9/4C4349858016/SIP/Info/sipSPIUpdateSrcSdpVariablePart: SIP update src sdp, negoitated codec 5, payload type 0 Aug 12 12:52:05.846: //9/4C4349858016/SIP/Info/sipSPIAddBillingInfoToCcb: sipCallId for billing records = NjgyZTFkNzRkYWI4ZjBkZWVkODQ4MmFmMTQ4NGRmNWQ. Aug 12 12:52:05.846: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentCPA: No CPA found in inbound container Aug 12 12:52:05.846: //9/4C4349858016/SIP/Info/sipSPIProcessCPA: No x-cisco-cpa content found Aug 12 12:52:05.846: //9/4C4349858016/SIP/Info/sipSPI_ipip_GetHdrPassthruCfg: Hdr passthrough config:1 tag:0 Aug 12 12:52:05.846: //9/4C4349858016/SIP/Info/sipSPI_ipip_ExtractPassthruCopyListHdrsFromSipContainer: Unsupported header passthru is not configured and no headers are present in hdr_hash_queue Aug 12 12:52:05.846: //9/4C4349858016/SIP/Info/sipSPI_ipip_IsContentPassthruEnabled: - 0 Aug 12 12:52:05.846: //9/4C4349858016/SIP/Info/sipSPI_ipip_ExtractPassthruContentFromSipContainer: Passthru Content Not Enabled Aug 12 12:52:05.846: //9/4C4349858016/SIP/Info/ccsip_api_call_setup_ind: Unable to add unsupp headers to container Aug 12 12:52:05.846: //9/4C4349858016/SIP/Info/ccsip_api_call_setup_ind: Set Protocol information Aug 12 12:52:05.850: //9/4C4349858016/SIP/Info/ccsip_ipip_media_service_get_event_data: Event id = 24 Aug 12 12:52:05.850: //9/4C4349858016/SIP/Info/sipSPI_ipip_antiTrombone: Entered Antitrombone service Aug 12 12:52:05.850: //9/4C4349858016/SIP/Info/sipSPI_ipip_antiTrombone: Antitrombone service not configured Aug 12 12:52:05.850: //9/4C4349858016/SIP/Info/sipSPI_ipip_store_channel_info: Store channelInfo in CallInfo Aug 12 12:52:05.850: //9/4C4349858016/SIP/Info/sipSPI_ipip_store_channel_info: dtmf negotiation done, storing negotiated dtmf = 0, Aug 12 12:52:05.850: //9/4C4349858016/SIP/Media/sipSPIDisplayStreamInfo: Stream type : voice-only Media line : 1 State : STREAM_ADDING (2) Stream address type : 1 Callid : 9 Peer Callid : -1 RTP/SRTP Negotiated : 8 Negotiated Codec : g711ulaw, bytes :160 Nego. Codec payload : 0 (tx), 0 (rx) Negotiated DTMF relay : inband-voice Negotiated NTE payload : 0 (tx), 0 (rx) Negotiated CN payload : 13 Media Srce Addr/Port : [10.244.3.1]:17758 Media Dest Addr/Port : [10.30.0.7]:39572 Aug 12 12:52:05.850: //9/4C4349858016/SIP/Info/sipSPI_ipip_calculate_channel_count: Number of streams to report = 1 Aug 12 12:52:05.850: //9/4C4349858016/SIP/Info/sipSPI_ipip_store_channel_info: Setting CHANNEL_COUNT = 1 for callid 9 Aug 12 12:52:05.850: //9/4C4349858016/SIP/Info/sipSPIShrlCall: Check peer: 1 for Shared-Line call, callid: 9 Aug 12 12:52:05.850: //9/4C4349858016/SIP/Info/ccsip_set_bearer_capability: Bearer Capability: Speech (0x00) Aug 12 12:52:05.850: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentQSIG: No QSIG Body found in inbound container Aug 12 12:52:05.850: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentQ931: No RawMsg Body found in inbound container Aug 12 12:52:05.850: //-1/xxxxxxxxxxxx/SIP/Info/sipSPICreateNewRawMsg: No Data to form The Raw Message Aug 12 12:52:05.850: //9/4C4349858016/SIP/Info/sipSPIContinueNewMsgInvite: ccsip_api_call_setup_ind returned: SIP_SUCCESS Aug 12 12:52:05.850: //9/4C4349858016/SIP/Info/sipSPIUaddccCallIdToTable: Adding call id 9 to table Aug 12 12:52:05.850: //9/4C4349858016/SIP/Info/sipSPIUpdateCallEntry: Call 9 set InfoType to SPEECH Aug 12 12:52:05.850: //9/4C4349858016/SIP/Event/Session-Timer/sipSTSLMain: Event: E_STSL_SESSION_REFRESH_RESP Aug 12 12:52:05.850: //9/4C4349858016/SIP/Event/Session-Timer/sipSTSLMain: dir:1, method:102, resp_code:100, container:88C2F344 Aug 12 12:52:05.850: //9/4C4349858016/SIP/Info/Session-Timer/sipSTSLValidateSessRefreshMsg: Ignoring 1xx response for session timer processing Aug 12 12:52:05.850: //9/4C4349858016/SIP/Info/sipSPISendInviteResponse: Associated container=0x88C2F344 to Invite Response 100 Aug 12 12:52:05.850: //9/4C4349858016/SIP/Transport/sipSPITransportSendMessage: msg=0x8831C3F4, addr=10.30.0.2, port=5060, sentBy_port=5060, local_addr=10.244.3.1, is_req=0, transport=1, switch=0, callBack=0x0 Aug 12 12:52:05.850: //9/4C4349858016/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Aug 12 12:52:05.850: //9/4C4349858016/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0 Aug 12 12:52:05.850: //9/4C4349858016/SIP/Transport/sipTransportLogicSendMsg: Trying to send resp=0x8831C3F4 to default port=5060 Aug 12 12:52:05.850: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:10.30.0.2, rport:5060 with laddr:10.244.3.1 Aug 12 12:52:05.850: //9/4C4349858016/SIP/Transport/sipTransportLogicSendMsg: Connection obtained...sending msg=0x8831C3F4 Aug 12 12:52:05.850: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x8831C3F4, addr=10.30.0.2, port=5060, local_addr=10.244.3.1, connId=3 for UDP Aug 12 12:52:05.850: //9/4C4349858016/SIP/State/sipSPIChangeState: 0x889B18C8 : State change from (STATE_IDLE, SUBSTATE_NONE) to (STATE_RECD_INVITE, SUBSTATE_NONE) Aug 12 12:52:05.850: //9/4C4349858016/SIP/Info/sipSPIProcessContactInfo: Previous Hop 10.30.0.2:5060 Aug 12 12:52:05.854: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_PROCEEDING Aug 12 12:52:05.854: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_event_handler: switch(ev.ev_id: 176) Aug 12 12:52:05.854: //9/4C4349858016/SIP/Info/ccsip_event_handler: Current mode is SIP-TDM Aug 12 12:52:05.854: //9/4C4349858016/SIP/Info/ccsip_iwf_handle_peer_event: Aug 12 12:52:05.854: //9/4C4349858016/SIP/Info/ccsip_iwf_map_ccapi_event_to_iwf_event: Event Category: 1, Event Id: 176 Aug 12 12:52:05.854: //9/4C4349858016/SIP/Info/ccsip_iwf_process_event: Aug 12 12:52:05.854: //9/4C4349858016/SIP/State/ccsip_cnfsm_debugs: IWF:cur_container:sip_iwf_default_early_dialog_container, cur_state:S_SIP_IWF_SDP_RCVD_AWAIT_PEER_EVENT, event:E_SIP_IWF_EV_SET_MODE Aug 12 12:52:05.854: //9/4C4349858016/SIP/State/ccsip_cnfsm_debugs: IWF:new_container:sip_iwf_main_container Aug 12 12:52:05.854: //9/4C4349858016/SIP/Info/ccsip_get_int_type_frm_set_mode_ev: Aug 12 12:52:05.854: //9/4C4349858016/SIP/Info/is_mode_sip_sip_md: Aug 12 12:52:05.854: //9/4C4349858016/SIP/Info/ccsip_get_int_type_frm_set_mode_ev: Aug 12 12:52:05.854: //9/4C4349858016/SIP/Info/is_mode_sip_sip_ed: Aug 12 12:52:05.854: //9/4C4349858016/SIP/Info/ccsip_get_int_type_frm_set_mode_ev: Aug 12 12:52:05.854: //9/4C4349858016/SIP/Info/is_mode_sip_h32x_in_set_mode: Aug 12 12:52:05.854: //9/4C4349858016/SIP/Info/ccsip_get_int_type_frm_set_mode_ev: Aug 12 12:52:05.854: //9/4C4349858016/SIP/Info/is_mode_sip_h323_in_set_mode: Aug 12 12:52:05.854: //9/4C4349858016/SIP/Info/ccsip_get_int_type_frm_set_mode_ev: Aug 12 12:52:05.854: //9/4C4349858016/SIP/Info/is_mode_sip_sccp_in_set_mode: Aug 12 12:52:05.854: //9/4C4349858016/SIP/Info/ccsip_get_int_type_frm_set_mode_ev: Aug 12 12:52:05.854: //9/4C4349858016/SIP/Info/is_mode_sip_sccp_in_set_mode: Aug 12 12:52:05.854: //9/4C4349858016/SIP/Info/sip_iwf_def_set_mode_hdlr: Setting SPI mode to SIP-TDM Aug 12 12:52:05.854: //9/4C4349858016/SIP/State/ccsip_cnfsm_debugs: IWF:new_container:sip_iwf_sccp_early_dialog_container Aug 12 12:52:05.854: //9/4C4349858016/SIP/State/ccsip_cnfsm_debugs: IWF:next_state:CNFSM_NO_STATE_CHANGEmote-Party-ID: "Assistente 1" ;party=called;screen=no;privacy=off Contact: Server: Cisco-SIPGateway/IOS-12.x Content-Length: 0 Aug 12 12:52:06.898: //9/4C4349858016/SIP/Info/sipSPIResendInviteResponse: resending 180 response due to no PRACK Aug 12 12:52:06.898: //9/4C4349858016/SIP/Event/sipSPICreateRpid: Received Octet3A=0x00 -> Setting ;screen=no ;privacy=off Aug 12 12:52:06.898: //9/4C4349858016/SIP/Info/sipSPISendInviteResponse: Associated container=0x88C2EB04 to Invite Response 180 Aug 12 12:52:06.898: //9/4C4349858016/SIP/Transport/sipSPISendInviteResponse: Sending 180 Response to the Transport Layer Aug 12 12:52:06.898: //9/4C4349858016/SIP/Transport/sipSPITransportSendMessage: msg=0x86802E68, addr=10.30.0.2, port=5060, sentBy_port=5060, local_addr=10.244.3.1, is_req=0, transport=1, switch=0, callBack=0x0 Aug 12 12:52:06.898: //9/4C4349858016/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Aug 12 12:52:06.898: //9/4C4349858016/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0 Aug 12 12:52:06.898: //9/4C4349858016/SIP/Transport/sipTransportLogicSendMsg: Trying to send resp=0x86802E68 to default port=5060 Aug 12 12:52:06.898: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:10.30.0.2, rport:5060 with laddr:10.244.3.1 Aug 12 12:52:06.898: //9/4C4349858016/SIP/Transport/sipTransportLogicSendMsg: Connection obtained...sending msg=0x86802E68 Aug 12 12:52:06.898: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x86802E68, addr=10.30.0.2, port=5060, local_addr=10.244.3.1, connId=3 for UDP Aug 12 12:52:06.902: //9/4C4349858016/SIP/Msg/ccsipDisplayMsg: Sent: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.30.0.2:5060;branch=z9hG4bK-d8754z-d8c489750d22503d-1---d8754z-;rport From: "TESTE ANGOLA";tag=1f30f315 To: ;tag=52C41F8-1756 Date: Tue, 12 Aug 2014 12:52:05 GMT Call-ID: NjgyZTFkNzRkYWI4ZjBkZWVkODQ4MmFmMTQ4NGRmNWQ. CSeq: 1 INVITE Require: 100rel RSeq: 515 Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER Allow-Events: telephone-event Remote-Party-ID: "Assistente 1" ;party=called;screen=no;privacy=off Contact: Server: Cisco-SIPGateway/IOS-12.x Content-Length: 0 Aug 12 12:52:07.442: //9/4C4349858016/SIP/Info/sipSPIResendInviteResponse: resending 180 response due to no PRACK Aug 12 12:52:07.446: //9/4C4349858016/SIP/Event/sipSPICreateRpid: Received Octet3A=0x00 -> Setting ;screen=no ;privacy=off Aug 12 12:52:07.446: //9/4C4349858016/SIP/Info/sipSPISendInviteResponse: Associated container=0x88C2EB04 to Invite Response 180 Aug 12 12:52:07.446: //9/4C4349858016/SIP/Transport/sipSPISendInviteResponse: Sending 180 Response to the Transport Layer Aug 12 12:52:07.446: //9/4C4349858016/SIP/Transport/sipSPITransportSendMessage: msg=0x86802E68, addr=10.30.0.2, port=5060, sentBy_port=5060, local_addr=10.244.3.1, is_req=0, transport=1, switch=0, callBack=0x0 Aug 12 12:52:07.446: //9/4C4349858016/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Aug 12 12:52:07.446: //9/4C4349858016/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0 Aug 12 12:52:07.446: //9/4C4349858016/SIP/Transport/sipTransportLogicSendMsg: Trying to send resp=0x86802E68 to default port=5060 Aug 12 12:52:07.446: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:10.30.0.2, rport:5060 with laddr:10.244.3.1 Aug 12 12:52:07.446: //9/4C4349858016/SIP/Transport/sipTransportLogicSendMsg: Connection obtained...sending msg=0x86802E68 Aug 12 12:52:07.446: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x86802E68, addr=10.30.0.2, port=5060, local_addr=10.244.3.1, connId=3 for UDP Aug 12 12:52:07.446: //9/4C4349858016/SIP/Msg/ccsipDisplayMsg: Sent: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.30.0.2:5060;branch=z9hG4bK-d8754z-d8c489750d22503d-1---d8754z-;rport From: "TESTE ANGOLA";tag=1f30f315 To: ;tag=52C41F8-1756 Date: Tue, 12 Aug 2014 12:52:05 GMT Call-ID: NjgyZTFkNzRkYWI4ZjBkZWVkODQ4MmFmMTQ4NGRmNWQ. CSeq: 1 INVITE Require: 100rel RSeq: 515 Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER Allow-Events: telephone-event Remote-Party-ID: "Assistente 1" ;party=called;screen=no;privacy=off Contact: Server: Cisco-SIPGateway/IOS-12.x Content-Length: 0 Aug 12 12:52:08.346: //9/4C4349858016/SIP/Info/ccsip_query_codec_info: Negotiated codec = 5 Aug 12 12:52:08.346: //9/4C4349858016/SIP/Info/sipSPI_ipip_codec_byte_transrating: NOT SIP-SIP CALL. Will be addressed in future. Aug 12 12:52:08.346: //9/4C4349858016/SIP/Info/ccsip_bridge: confID = 4, srcCallID = 9, dstCallID = 10 Aug 12 12:52:08.346: //9/4C4349858016/SIP/Info/sipSPIUupdateCcCallIds: Old src/dest ccCallids: -1/-1, new src/dest ccCallids: 9/10 Aug 12 12:52:08.350: //9/4C4349858016/SIP/Info/sipSPIUupdateCcCallIds: Old streamcallid=9, new streamcallid=9 Aug 12 12:52:08.350: //9/4C4349858016/SIP/Info/ccsip_gw_set_sipspi_mode: Setting SPI mode to SIP-TDM Aug 12 12:52:08.350: //9/4C4349858016/SIP/Info/ccsip_iwf_handle_generic_event: Aug 12 12:52:08.350: //9/4C4349858016/SIP/Info/ccsip_iwf_process_event: Aug 12 12:52:08.350: //9/4C4349858016/SIP/State/ccsip_cnfsm_debugs: IWF:cur_container:sip_iwf_sccp_early_dialog_container, cur_state:S_SIP_IWF_SDP_RCVD_AWAIT_PEER_EVENT, event:E_SIP_IWF_EV_CALL_BRIDGE Aug 12 12:52:08.350: //9/4C4349858016/SIP/State/ccsip_cnfsm_debugs: IWF:new_container:sip_iwf_main_container Aug 12 12:52:08.350: //9/4C4349858016/SIP/Info/ccsip_iwf_process_event: IWF - cnfsm ret 2 Aug 12 12:52:08.350: //9/4C4349858016/SIP/Info/ccsip_bridge: xcoder_attached = 0, xmitFunc = -2139178220, ccb xmitFunc = -2139178220 Aug 12 12:52:08.350: //9/4C4349858016/SIP/Info/ccsip_spi_check_call_locally_held: CCSIP: call is locally noton-hold Aug 12 12:52:08.350: //9/4C4349858016/SIP/Media/sipSPIAddStream: Adding stream 1 of type voice-only (callid 9) to the VOIP RTP library Aug 12 12:52:08.350: //9/4C4349858016/SIP/Info/sipSPIValidateStreamAddrType: stream:1, Mode : 1 Aug 12 12:52:08.350: //9/4C4349858016/SIP/Info/resolve_media_ip_address_to_bind: Media already bound, use existing source_media_ip_addr Aug 12 12:52:08.350: //9/4C4349858016/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 10.244.3.1 Aug 12 12:52:08.350: //9/4C4349858016/SIP/Media/sipSPIUpdateRtcpSession: sipSPIUpdateRtcpSession for m-line 1 Aug 12 12:52:08.350: //9/4C4349858016/SIP/Media/sipSPIUpdateRtcpSession: rtcp_session info laddr = 10.244.3.1, lport = 17758, raddr = 10.30.0.7, rport=39572, do_rtcp=TRUE src_callid = 9, dest_callid = 10, stream type = voice-only, stream direction = SENDRECV media_ip_addr = 10.30.0.7, vrf tableid = 0 media_addr_type = 1 Aug 12 12:52:08.350: //9/4C4349858016/SIP/Media/sipSPIUpdateRtcpSession: No rtp session, creating a new one Aug 12 12:52:08.350: //9/4C4349858016/SIP/Info/sipSPICreateRtpSession: sess: 88EDF5F4 do_rtcp:1 Aug 12 12:52:08.350: //9/4C4349858016/SIP/Media/sipSPICreateRtpSession: stun is disabled Aug 12 12:52:08.350: //9/4C4349858016/SIP/Info/sipSPICreateAndStartRtpTimer: Media Inactivity Timer is disabled. Aug 12 12:52:08.350: //9/4C4349858016/SIP/Info/sipSPI_ipip_is_escalation: local channels = 1, peer channels = 0 Aug 12 12:52:08.350: //9/4C4349858016/SIP/Media/sipSPIGetNewLocalMediaDirection: New Remote Media Direction = SENDRECV Present Local Media Direction = SENDRECV New Local Media Direction = SENDRECV retVal = 0 Aug 12 12:52:08.350: //9/4C4349858016/SIP/State/sipSPIChangeStreamState: Stream (callid = 9) State changed from (STREAM_ADDING) to (STREAM_ACTIVE) Aug 12 12:52:08.350: //9/4C4349858016/SIP/Info/ccsip_iwf_handle_peer_event: Aug 12 12:52:08.350: //9/4C4349858016/SIP/Info/ccsip_iwf_map_ccapi_event_to_iwf_event: Event Category: 3, Event Id: 25 Aug 12 12:52:08.350: //9/4C4349858016/SIP/Info/ccsip_iwf_process_event: Aug 12 12:52:08.350: //9/4C4349858016/SIP/State/ccsip_cnfsm_debugs: IWF:cur_container:sip_iwf_sccp_early_dialog_container, cur_state:S_SIP_IWF_SDP_RCVD_AWAIT_PEER_EVENT, event:E_SIP_IWF_EV_PEER_CAPS Aug 12 12:52:08.350: //9/4C4349858016/SIP/State/ccsip_cnfsm_debugs: IWF:new_container:sip_iwf_main_container Aug 12 12:52:08.350: //9/4C4349858016/SIP/Info/is_mode_sip_sccp_do_video: Aug 12 12:52:08.350: //9/4C4349858016/SIP/Info/sip_iwf_def_peer_caps_ind_hdlr: Aug 12 12:52:08.350: //9/4C4349858016/SIP/Info/ccsip_get_rtcp_session_parameters: CURRENT VALUES: stream_callid=9, current_seq_num=0xFC1 Aug 12 12:52:08.350: //9/4C4349858016/SIP/Info/ccsip_get_rtcp_session_parameters: NEW VALUES: stream_callid=9, current_seq_num=0x19BF Aug 12 12:52:08.350: //9/4C4349858016/SIP/Info/sip_iwf_def_process_caps_ind: Load DSP with negotiated codec: g711ulaw, Bytes=160 Aug 12 12:52:08.350: //9/4C4349858016/SIP/Info/sip_iwf_def_process_caps_ind: Set forking flag to 0x0 Aug 12 12:52:08.350: //9/4C4349858016/SIP/Info/sipSPISetDTMFRelayMode: Set DSP for dtmf-relay = CC_CAP_DTMF_RELAY_INBAND_VOICE_AND_OOB Aug 12 12:52:08.350: //9/4C4349858016/SIP/Info/sip_set_modem_caps: Preferred (or the one that came from DSM) modem relay=0, from CLI config=0 Aug 12 12:52:08.350: //9/4C4349858016/SIP/Info/sipSPIGetModemInfoPerCall: peer_callID=10 Aug 12 12:52:08.350: //9/4C4349858016/SIP/Info/sip_set_modem_caps: Disabling Modem Relay... Aug 12 12:52:08.354: //9/4C4349858016/SIP/Info/sip_generate_sdp_xcaps_list: Modem Relay and T38 disabled. X-cap not needed Aug 12 12:52:08.354: //9/4C4349858016/SIP/Info/sip_set_modem_caps: Negotiation already Done. Set negotiated Modem caps and generate SDP Xcap list Aug 12 12:52:08.354: //9/4C4349858016/SIP/Info/sip_set_modem_caps: Modem Relay & Passthru both disabled Aug 12 12:52:08.354: //9/4C4349858016/SIP/Info/sip_set_modem_caps: nse payload = 0, ptru mode = 0, ptru-codec=0, redundancy=0, xid=0, relay=0, sprt-retry=12, latecncy=200, compres-dir=3, dict=1024, strnlen=32 Aug 12 12:52:08.354: //9/4C4349858016/SIP/Media/sipSPISetStreamInfo: 1 Active Streams Aug 12 12:52:08.354: //9/4C4349858016/SIP/Media/sipSPISetStreamInfo: Adding stream type (voice-only) from media line 1 codec g711ulaw Aug 12 12:52:08.354: //9/4C4349858016/SIP/Media/sipSPISetStreamInfo: caps.stream_count=1,caps.stream[0].stream_type=0x1, caps.stream_list.xmitFunc= Aug 12 12:52:08.354: //9/4C4349858016/SIP/Media/sipSPISetStreamInfo: voip_rtp_xmit, caps.stream_list.context= Aug 12 12:52:08.354: //9/4C4349858016/SIP/Media/sipSPISetStreamInfo: 0x86694F80 (gccb) Aug 12 12:52:08.354: //9/4C4349858016/SIP/Info/sip_iwf_def_process_caps_ind: Load DSP with codec : g711ulaw, Bytes=160, payload = 0 Aug 12 12:52:08.354: //9/4C4349858016/SIP/Info/sip_iwf_def_process_caps_ind: ccsip_caps_ind: ccb->pld.flags_ipip = 0x203 Aug 12 12:52:08.354: //9/4C4349858016/SIP/Info/sip_iwf_def_process_caps_ind: Calling cc_api_caps_ack() Aug 12 12:52:08.354: //9/4C4349858016/SIP/Info/ccsip_ipip_media_service_get_event_data: Event id = 7 Aug 12 12:52:08.354: //9/4C4349858016/SIP/State/ccsip_cnfsm_debugs: IPIPMS:cur_container:ccsip_ipip_media_service_main_container, cur_state:S_IPIP_MEDIA_SERV_STATE_IDLE, event:E_IPIP_MEDIA_SERV_EV_PEER_CAPS_IND Aug 12 12:52:08.354: //9/4C4349858016/SIP/State/ccsip_cnfsm_debugs: IWF:next_state:CNFSM_NO_STATE_CHANGE Aug 12 12:52:08.354: //9/4C4349858016/SIP/Info/ccsip_iwf_handle_peer_event: Return value : SIP_IWF_SUCCESS Aug 12 12:52:08.354: //9/4C4349858016/SIP/Info/ccsip_iwf_map_cc_return_code: Mapping SIP_IWF_SUCCESS Aug 12 12:52:08.354: //9/4C4349858016/SIP/Info/ccsip_iwf_handle_peer_event: Aug 12 12:52:08.354: //9/4C4349858016/SIP/Info/ccsip_iwf_map_ccapi_event_to_iwf_event: Event Category: 3, Event Id: 26 Aug 12 12:52:08.354: //9/4C4349858016/SIP/Info/ccsip_iwf_process_event: Aug 12 12:52:08.354: //9/4C4349858016/SIP/State/ccsip_cnfsm_debugs: IWF:cur_container:sip_iwf_sccp_early_dialog_container, cur_state:S_SIP_IWF_SDP_RCVD_AWAIT_PEER_EVENT, event:E_SIP_IWF_EV_PEER_CAPS_ACK, Aug 12 12:52:08.354: //9/4C4349858016/SIP/State/ccsip_cnfsm_debugs: IWF:new_container:sip_iwf_main_container Aug 12 12:52:08.354: //9/4C4349858016/SIP/Info/sip_iwf_def_peer_caps_ack_hdlr: Aug 12 12:52:08.354: //9/4C4349858016/SIP/Info/sip_iwf_tdm_process_caps_ack: Set forking flag to 0x0 Aug 12 12:52:08.354: //9/4C4349858016/SIP/State/ccsip_cnfsm_debugs: IWF:next_state:CNFSM_NO_STATE_CHANGE Aug 12 12:52:08.354: //9/4C4349858016/SIP/Info/ccsip_iwf_handle_peer_event: Return value : SIP_IWF_SUCCESS Aug 12 12:52:08.354: //9/4C4349858016/SIP/Info/ccsip_iwf_map_cc_return_code: Mapping SIP_IWF_SUCCESS Aug 12 12:52:08.354: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_call_connect: CCSIP_CALL_CONNECT: ccb ptr 889B18C8 Aug 12 12:52:08.354: //9/4C4349858016/SIP/Info/ccsip_iwf_handle_generic_event: Aug 12 12:52:08.354: //9/4C4349858016/SIP/Info/ccsip_iwf_process_event: Aug 12 12:52:08.354: //9/4C4349858016/SIP/State/ccsip_cnfsm_debugs: IWF:cur_container:sip_iwf_sccp_early_dialog_container, cur_state:S_SIP_IWF_SDP_RCVD_AWAIT_PEER_EVENT, event:E_SIP_IWF_EV_CALL_CONNECT Aug 12 12:52:08.354: //9/4C4349858016/SIP/State/ccsip_cnfsm_debugs: IWF:new_container:sip_iwf_main_container Aug 12 12:52:08.354: //9/4C4349858016/SIP/Info/sip_iwf_common_call_connect_hdlr: Aug 12 12:52:08.354: //9/4C4349858016/SIP/State/ccsip_cnfsm_debugs: IWF:next_state:CNFSM_NO_STATE_CHANGE Aug 12 12:52:08.354: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_call_connect: CCSIP_CALL_CONNECT: app_diaplay_name[Assistente 1] app_display_num[103] Aug 12 12:52:08.354: //9/4C4349858016/SIP/Info/ccsip_call_connect: CCSIP_CALL_CONNECT : KPML_CONFIGURED[FALSE] collect_digits[103] calledNumber[103] display_name[Assistente 1] display_num[103] Aug 12 12:52:08.354: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_CONNECT Aug 12 12:52:08.358: //-1/xxxxxxxxxxxx/SIP/Error/ccsip_call_service_msg: ccb NULL, unable to update the callinfo ui parameters Aug 12 12:52:08.358: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_MEDIA_EVENT Aug 12 12:52:08.358: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 7 Aug 12 12:52:08.358: //9/4C4349858016/SIP/Event/Session-Timer/sipSTSLMain: Event: E_STSL_SPI_EVENT Aug 12 12:52:08.358: //9/4C4349858016/SIP/Info/Session-Timer/sipSTSLMain: SE: 1800;refresher:none peer refresher:none, flags:2001, posted event:E_STSL_INVALID_PEER_EVENT, reason:4 Configured SE:1800, Configured Min-SE:1800 Aug 12 12:52:08.358: //9/4C4349858016/SIP/Info/sipSPIBufferCurrentEvent: Enqueueing event SIPSPI_EV_CC_CALL_CONNECT as Acknowledgment is not yet received.. Aug 12 12:52:08.358: //9/4C4349858016/SIP/Info/sipSPIEnqueueBufferEvent: Event SIPSPI_EV_CC_CALL_CONNECT queued on buffer queue. Aug 12 12:52:08.358: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 29 Aug 12 12:52:08.358: //9/4C4349858016/SIP/Event/Session-Timer/sipSTSLMain: Event: E_STSL_SPI_EVENT Aug 12 12:52:08.362: //9/4C4349858016/SIP/Info/Session-Timer/sipSTSLMain: SE: 1800;refresher:none peer refresher:none, flags:2001, posted event:E_STSL_INVALID_PEER_EVENT, reason:4 Configured SE:1800, Configured Min-SE:1800 Aug 12 12:52:09.626: //9/4C4349858016/SIP/Info/sipSPIResendInviteResponse: resending 180 response due to no PRACK Aug 12 12:52:09.626: //9/4C4349858016/SIP/Event/sipSPICreateRpid: Received Octet3A=0x00 -> Setting ;screen=no ;privacy=off Aug 12 12:52:09.626: //9/4C4349858016/SIP/Info/sipSPISendInviteResponse: Associated container=0x88C2EB04 to Invite Response 180 Aug 12 12:52:09.626: //9/4C4349858016/SIP/Transport/sipSPISendInviteResponse: Sending 180 Response to the Transport Layer Aug 12 12:52:09.626: //9/4C4349858016/SIP/Transport/sipSPITransportSendMessage: msg=0x874FB948, addr=10.30.0.2, port=5060, sentBy_port=5060, local_addr=10.244.3.1, is_req=0, transport=1, switch=0, callBack=0x0 Aug 12 12:52:09.626: //9/4C4349858016/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Aug 12 12:52:09.626: //9/4C4349858016/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0 Aug 12 12:52:09.626: //9/4C4349858016/SIP/Transport/sipTransportLogicSendMsg: Trying to send resp=0x874FB948 to default port=5060 Aug 12 12:52:09.626: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:10.30.0.2, rport:5060 with laddr:10.244.3.1 Aug 12 12:52:09.630: //9/4C4349858016/SIP/Transport/sipTransportLogicSendMsg: Connection obtained...sending msg=0x874FB948 Aug 12 12:52:09.630: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x874FB948, addr=10.30.0.2, port=5060, local_addr=10.244.3.1, connId=3 for UDP Aug 12 12:52:09.630: //9/4C4349858016/SIP/Msg/ccsipDisplayMsg: Sent: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.30.0.2:5060;branch=z9hG4bK-d8754z-d8c489750d22503d-1---d8754z-;rport From: "TESTE ANGOLA";tag=1f30f315 To: ;tag=52C41F8-1756 Date: Tue, 12 Aug 2014 12:52:05 GMT Call-ID: NjgyZTFkNzRkYWI4ZjBkZWVkODQ4MmFmMTQ4NGRmNWQ. CSeq: 1 INVITE Require: 100rel RSeq: 515 Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER Allow-Events: telephone-event Remote-Party-ID: "Assistente 1" ;party=called;screen=no;privacy=off Contact: Server: Cisco-SIPGateway/IOS-12.x Content-Length: 0 Aug 12 12:52:10.082: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [5.39.84.82]:5060, local_address:[10.244.3.1] Aug 12 12:52:10.082: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Aug 12 12:52:10.082: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x8751D4F4 Aug 12 12:52:10.082: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessNewConnMsg: gConnTab=0x8751D4F4, addr=5.39.84.82, port=5060, local_addr=10.244.3.1, connid=4, transport=UDP Aug 12 12:52:10.082: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: OPTIONS sip:7143167791@41.63.165.117:60417 SIP/2.0 Via: SIP/2.0/UDP 5.39.84.82:5060;branch=z9hG4bK5c8cf5f2;rport Max-Forwards: 70 From: "asterisk" ;tag=as3274f104 To: Contact: Call-ID: 5f5dc66409d8992743209a2605559cba@5.39.84.82:5060 CSeq: 102 OPTIONS User-Agent: ELITEVOIP-EUROPE-01 Date: Tue, 12 Aug 2014 12:57:54 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Content-Length: 0 Aug 12 12:52:10.082: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog Aug 12 12:52:10.082: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAddContextToTable: Added context(0x889B72B8) with key=[13] to table Aug 12 12:52:10.082: //-1/000000000000/SIP/Info/ccsip_offer_ans_init: Aug 12 12:52:10.082: //-1/000000000000/SIP/Info/ccsip_iwf_init: Aug 12 12:52:10.082: //-1/000000000000/SIP/Info/ccsip_ipip_media_service_init: Aug 12 12:52:10.082: //-1/000000000000/SIP/Info/sipSPI_ipip_vcc_Initialization: Entry... Aug 12 12:52:10.082: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 5.39.84.82,Port 5060, Transport 1, SentBy Port 5060 Aug 12 12:52:10.082: //-1/000000000000/SIP/Info/resolve_sig_ip_address_to_bind: signaling bind address : 10.244.3.1 Aug 12 12:52:10.082: //-1/4ECB7C95801C/SIP/State/sipSPIChangeState: 0x889B72B8 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE) Aug 12 12:52:10.082: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 5.39.84.82,Port 5060, Transport 1, SentBy Port 5060 Aug 12 12:52:10.082: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Converting TimeZone WAT to SIP default timezone = GMT Aug 12 12:52:10.082: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 5.39.84.82,Port 5060, Transport 1, SentBy Port 5060 Aug 12 12:52:10.082: //11/4ECB7C95801C/SIP/Info/ccsipInitPldCallingInfo: non-numeric calling number: asterisk Aug 12 12:52:10.082: //11/4ECB7C95801C/SIP/Info/sipSPIGetViaHostInURLFormat: VIA URL:sip:5.39.84.82:5060, Host:5.39.84.82 Aug 12 12:52:10.082: //11/4ECB7C95801C/SIP/Info/sipSPIGetShrlPeer: Try match incoming dialpeer for Calling number: : asterisk Aug 12 12:52:10.086: //11/4ECB7C95801C/SIP/Info/sipSPIGetFromCalledPartyId: P-Called-Party-ID header not found Aug 12 12:52:10.086: //11/4ECB7C95801C/SIP/Info/sipSPIGetPeerByCalledPartyId: P-Called-Party-ID not found or parse error Aug 12 12:52:10.086: //11/4ECB7C95801C/SIP/Info/sipSPIGetCallConfig: No match found for P-Called-Party-ID Aug 12 12:52:10.086: //11/4ECB7C95801C/SIP/Info/sipSPIGetCallConfig: Precondition tag absent in Require/Supported header Aug 12 12:52:10.086: //11/4ECB7C95801C/SIP/Info/sipSPIGetCallConfig: Media Antitrombone disabled Aug 12 12:52:10.086: //11/4ECB7C95801C/SIP/Info/sipSPISetMediaFlowMode: Storing the configured mode as FLOW-THROUGH Aug 12 12:52:10.086: //11/4ECB7C95801C/SIP/Info/sipSPISetMediaFlowMode: xcoder high-density disabled Aug 12 12:52:10.086: //11/4ECB7C95801C/SIP/Info/sipSPISetMediaFlowMode: Flow Mode set to FLOW_THROUGH Aug 12 12:52:10.086: //11/4ECB7C95801C/SIP/Info/sipSPIGetCallConfig: Non dial peer leg - using RTP Supported Codecs Aug 12 12:52:10.086: //11/4ECB7C95801C/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 18 Aug 12 12:52:10.086: //11/4ECB7C95801C/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 0 Aug 12 12:52:10.086: //11/4ECB7C95801C/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 8 Aug 12 12:52:10.086: //11/4ECB7C95801C/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 9 Aug 12 12:52:10.086: //11/4ECB7C95801C/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 4 Aug 12 12:52:10.086: //11/4ECB7C95801C/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 2 Aug 12 12:52:10.086: //11/4ECB7C95801C/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 15 Aug 12 12:52:10.086: //11/4ECB7C95801C/SIP/Info/sipSPIGetCallConfig: RTP Preferred Codecs supported by GW 3 Aug 12 12:52:10.086: //11/4ECB7C95801C/SIP/Info/sipSPIGetModemInfoPerCall: peer_callID=0 Aug 12 12:52:10.086: //11/4ECB7C95801C/SIP/Info/sipSPISetOverlapConfiguration: Overlap signaling: FALSE: Endpt: SIP Trunk Aug 12 12:52:10.086: //11/4ECB7C95801C/SIP/Info/sipSPI_ipip_GetHdrPassthruCfg: Hdr passthrough config:1 tag:0 Aug 12 12:52:10.086: //11/4ECB7C95801C/SIP/Info/sipSPI_ipip_GetCopyListCfg: Copy-list config:2 tag:0 Aug 12 12:52:10.086: //11/4ECB7C95801C/SIP/Info/sipSPI_ipip_build_consolidated_header_list: Both passthru and copylist are disabled Aug 12 12:52:10.086: //11/4ECB7C95801C/SIP/Info/sipSPIValidateStreamAddrType: stream:1, Mode : 1 Aug 12 12:52:10.086: //11/4ECB7C95801C/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 10.244.3.1 Aug 12 12:52:10.086: //11/4ECB7C95801C/SIP/Info/resolve_sig_ip_address_to_bind: signaling bind address : 10.244.3.1 Aug 12 12:52:10.086: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_OPTIONS_RESP Aug 12 12:52:10.086: //11/4ECB7C95801C/SIP/Info/sact_idle_new_message_options: ccsip_api_options_ind returned: SIP_SUCCESS Aug 12 12:52:10.086: //11/4ECB7C95801C/SIP/State/sipSPIChangeState: 0x889B72B8 : State change from (STATE_IDLE, SUBSTATE_NONE) to (SIP_STATE_OPTIONS_WAIT, SUBSTATE_NONE) Aug 12 12:52:10.086: //11/4ECB7C95801C/SIP/Info/sipSPIUaddCcbToUASReqTable: ****Adding to UAS Request table. Aug 12 12:52:10.086: //11/4ECB7C95801C/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x889B72B8 key=5f5dc66409d8992743209a2605559cba@5.39.84.82:50607143167791 Aug 12 12:52:10.086: //11/4ECB7C95801C/SIP/Info/sipSPIUaddccCallIdToTable: Adding call id B to table Aug 12 12:52:10.086: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 38 Aug 12 12:52:10.086: //11/4ECB7C95801C/SIP/Info/sipSPISendOptionsResponse: Associated container=0x88C2E8F4 to Options Response Aug 12 12:52:10.090: //11/4ECB7C95801C/SIP/Transport/sipSPITransportSendMessage: msg=0x8A23368C, addr=5.39.84.82, port=5060, sentBy_port=5060, local_addr=10.244.3.1, is_req=0, transport=1, switch=0, callBack=0x814AD178 Aug 12 12:52:10.090: //11/4ECB7C95801C/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Aug 12 12:52:10.090: //11/4ECB7C95801C/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0 Aug 12 12:52:10.090: //11/4ECB7C95801C/SIP/Transport/sipTransportLogicSendMsg: Trying to send resp=0x8A23368C to default port=5060 Aug 12 12:52:10.090: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:5.39.84.82, rport:5060 with laddr:10.244.3.1 Aug 12 12:52:10.090: //11/4ECB7C95801C/SIP/Transport/sipTransportLogicSendMsg: Connection obtained...sending msg=0x8A23368C Aug 12 12:52:10.090: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x8A23368C, addr=5.39.84.82, port=5060, local_addr=10.244.3.1, connId=4 for UDP Aug 12 12:52:10.090: //11/4ECB7C95801C/SIP/Msg/ccsipDisplayMsg: Sent: SIP/2.0 200 OK Via: SIP/2.0/UDP 5.39.84.82:5060;branch=z9hG4bK5c8cf5f2;rport From: "asterisk" ;tag=as3274f104 To: ;tag=52C5270-14A7 Date: Tue, 12 Aug 2014 12:52:10 GMT Call-ID: 5f5dc66409d8992743209a2605559cba@5.39.84.82:5060 Server: Cisco-SIPGateway/IOS-12.x CSeq: 102 OPTIONS Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER Allow-Events: telephone-event Accept: application/sdp Supported: 100rel,timer,resource-priority,replaces,sdp-anat Content-Type: application/sdp Content-Length: 162 v=0 o=CiscoSystemsSIP-GW-UserAgent 235 4986 IN IP4 10.244.3.1 s=SIP Call c=IN IP4 10.244.3.1 t=0 0 m=audio 0 RTP/AVP 18 0 8 9 4 2 15 3 c=IN IP4 10.244.3.1 Aug 12 12:52:11.822: //9/4C4349858016/SIP/Info/ccsip_indicate_rt_packet_stats: Processing stats for callid=9, proc_id=9 Aug 12 12:52:13.370: //9/4C4349858016/SIP/Info/sipSPIResendInviteResponse: resending 180 response due to no PRACK Aug 12 12:52:13.370: //9/4C4349858016/SIP/Event/sipSPICreateRpid: Received Octet3A=0x00 -> Setting ;screen=no ;privacy=off Aug 12 12:52:13.370: //9/4C4349858016/SIP/Info/sipSPISendInviteResponse: Associated container=0x88C2EB04 to Invite Response 180 Aug 12 12:52:13.370: //9/4C4349858016/SIP/Transport/sipSPISendInviteResponse: Sending 180 Response to the Transport Layer Aug 12 12:52:13.370: //9/4C4349858016/SIP/Transport/sipSPITransportSendMessage: msg=0x88EDDF80, addr=10.30.0.2, port=5060, sentBy_port=5060, local_addr=10.244.3.1, is_req=0, transport=1, switch=0, callBack=0x0 Aug 12 12:52:13.370: //9/4C4349858016/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Aug 12 12:52:13.370: //9/4C4349858016/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0 Aug 12 12:52:13.370: //9/4C4349858016/SIP/Transport/sipTransportLogicSendMsg: Trying to send resp=0x88EDDF80 to default port=5060 Aug 12 12:52:13.370: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:10.30.0.2, rport:5060 with laddr:10.244.3.1 Aug 12 12:52:13.370: //9/4C4349858016/SIP/Transport/sipTransportLogicSendMsg: Connection obtained...sending msg=0x88EDDF80 Aug 12 12:52:13.370: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x88EDDF80, addr=10.30.0.2, port=5060, local_addr=10.244.3.1, connId=3 for UDP Aug 12 12:52:13.370: //9/4C4349858016/SIP/Msg/ccsipDisplayMsg: Sent: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.30.0.2:5060;branch=z9hG4bK-d8754z-d8c489750d22503d-1---d8754z-;rport From: "TESTE ANGOLA";tag=1f30f315 To: ;tag=52C41F8-1756 Date: Tue, 12 Aug 2014 12:52:05 GMT Call-ID: NjgyZTFkNzRkYWI4ZjBkZWVkODQ4MmFmMTQ4NGRmNWQ. CSeq: 1 INVITE Require: 100rel RSeq: 515 Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER Allow-Events: telephone-event Remote-Party-ID: "Assistente 1" ;party=called;screen=no;privacy=off Contact: Server: Cisco-SIPGateway/IOS-12.x Content-Length: 0 Aug 12 12:52:15.094: //9/4C4349858016/SIP/Info/ccsip_indicate_rt_packet_stats: Processing stats for callid=9, proc_id=9 Aug 12 12:52:17.370: //9/4C4349858016/SIP/Info/sipSPIResendInviteResponse: resending 180 response due to no PRACK Aug 12 12:52:17.370: //9/4C4349858016/SIP/Event/sipSPICreateRpid: Received Octet3A=0x00 -> Setting ;screen=no ;privacy=off Aug 12 12:52:17.370: //9/4C4349858016/SIP/Info/sipSPISendInviteResponse: Associated container=0x88C2EB04 to Invite Response 180 Aug 12 12:52:17.370: //9/4C4349858016/SIP/Transport/sipSPISendInviteResponse: Sending 180 Response to the Transport Layer Aug 12 12:52:17.370: //9/4C4349858016/SIP/Transport/sipSPITransportSendMessage: msg=0x8660BC04, addr=10.30.0.2, port=5060, sentBy_port=5060, local_addr=10.244.3.1, is_req=0, transport=1, switch=0, callBack=0x0 Aug 12 12:52:17.370: //9/4C4349858016/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Aug 12 12:52:17.370: //9/4C4349858016/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0 Aug 12 12:52:17.370: //9/4C4349858016/SIP/Transport/sipTransportLogicSendMsg: Trying to send resp=0x8660BC04 to default port=5060 Aug 12 12:52:17.370: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:10.30.0.2, rport:5060 with laddr:10.244.3.1 Aug 12 12:52:17.370: //9/4C4349858016/SIP/Transport/sipTransportLogicSendMsg: Connection obtained...sending msg=0x8660BC04 Aug 12 12:52:17.370: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x8660BC04, addr=10.30.0.2, port=5060, local_addr=10.244.3.1, connId=3 for UDP Aug 12 12:52:17.370: //9/4C4349858016/SIP/Msg/ccsipDisplayMsg: Sent: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.30.0.2:5060;branch=z9hG4bK-d8754z-d8c489750d22503d-1---d8754z-;rport From: "TESTE ANGOLA";tag=1f30f315 To: ;tag=52C41F8-1756 Date: Tue, 12 Aug 2014 12:52:05 GMT Call-ID: NjgyZTFkNzRkYWI4ZjBkZWVkODQ4MmFmMTQ4NGRmNWQ. CSeq: 1 INVITE Require: 100rel RSeq: 515 Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER Allow-Events: telephone-event Remote-Party-ID: "Assistente 1" ;party=called;screen=no;privacy=off Contact: Server: Cisco-SIPGateway/IOS-12.x Content-Length: 0 Aug 12 12:52:18.550: //9/4C4349858016/SIP/Info/ccsip_indicate_rt_packet_stats: Processing stats for callid=9, proc_id=9 Aug 12 12:52:21.370: //9/4C4349858016/SIP/Info/sipSPIResendInviteResponse: resending 180 response due to no PRACK Aug 12 12:52:21.370: //9/4C4349858016/SIP/Event/sipSPICreateRpid: Received Octet3A=0x00 -> Setting ;screen=no ;privacy=off Aug 12 12:52:21.370: //9/4C4349858016/SIP/Info/sipSPISendInviteResponse: Associated container=0x88C2EB04 to Invite Response 180 Aug 12 12:52:21.370: //9/4C4349858016/SIP/Transport/sipSPISendInviteResponse: Sending 180 Response to the Transport Layer Aug 12 12:52:21.370: //9/4C4349858016/SIP/Transport/sipSPITransportSendMessage: msg=0x866420C4, addr=10.30.0.2, port=5060, sentBy_port=5060, local_addr=10.244.3.1, is_req=0, transport=1, switch=0, callBack=0x0 Aug 12 12:52:21.370: //9/4C4349858016/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Aug 12 12:52:21.370: //9/4C4349858016/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0 Aug 12 12:52:21.370: //9/4C4349858016/SIP/Transport/sipTransportLogicSendMsg: Trying to send resp=0x866420C4 to default port=5060 Aug 12 12:52:21.370: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:10.30.0.2, rport:5060 with laddr:10.244.3.1 Aug 12 12:52:21.370: //9/4C4349858016/SIP/Transport/sipTransportLogicSendMsg: Connection obtained...sending msg=0x866420C4 Aug 12 12:52:21.370: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x866420C4, addr=10.30.0.2, port=5060, local_addr=10.244.3.1, connId=3 for UDP Aug 12 12:52:21.370: //9/4C4349858016/SIP/Msg/ccsipDisplayMsg: Sent: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.30.0.2:5060;branch=z9hG4bK-d8754z-d8c489750d22503d-1---d8754z-;rport From: "TESTE ANGOLA";tag=1f30f315 To: ;tag=52C41F8-1756 Date: Tue, 12 Aug 2014 12:52:05 GMT Call-ID: NjgyZTFkNzRkYWI4ZjBkZWVkODQ4MmFmMTQ4NGRmNWQ. CSeq: 1 INVITE Require: 100rel RSeq: 515 Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER Allow-Events: telephone-event Remote-Party-ID: "Assistente 1" ;party=called;screen=no;privacy=off Contact: Server: Cisco-SIPGateway/IOS-12.x Content-Length: 0 Aug 12 12:52:25.370: //9/4C4349858016/SIP/Error/act_sentrel1xx_wait_prack: Out of retries state:14 Aug 12 12:52:25.370: //9/4C4349858016/SIP/Info/ccsip_set_cc_cause_for_spi_err: Categorized cause:102, category:129 Aug 12 12:52:25.370: //9/4C4349858016/SIP/Info/ccsip_set_release_source_for_peer: ownCallId[9], src[6] Aug 12 12:52:25.370: //9/4C4349858016/SIP/Info/sipSPIInitiateDisconnect: Initiate call disconnect(102) for incoming call Aug 12 12:52:25.370: //-1/xxxxxxxxxxxx/SIP/Error/sipSPIGetContentQSIG: No Inbound Container Created !!! Aug 12 12:52:25.370: //-1/xxxxxxxxxxxx/SIP/Error/sipSPIGetContentQ931: No Inbound Container Created !!! Aug 12 12:52:25.370: //9/4C4349858016/SIP/Info/ccsip_ipip_media_service_get_event_data: Event id = 26 Aug 12 12:52:25.370: //9/4C4349858016/SIP/Info/sipSPI_ipip_antiTrombone: Entered Antitrombone service Aug 12 12:52:25.370: //9/4C4349858016/SIP/Info/sipSPI_ipip_antiTrombone: Antitrombone service not configured Aug 12 12:52:25.370: //9/4C4349858016/SIP/State/sipSPIChangeState: 0x889B18C8 : State change from (STATE_SENT_ALERTING, SUBSTATE_NONE) to (STATE_DISCONNECTING, SUBSTATE_NONE) Aug 12 12:52:25.370: //9/4C4349858016/SIP/Transport/sipSPISendErrorResponse: Sending ERROR Response to the transport layer Aug 12 12:52:25.370: //9/4C4349858016/SIP/Transport/sipSPITransportSendMessage: msg=0x88B01768, addr=10.30.0.2, port=5060, sentBy_port=5060, local_addr=10.244.3.1, is_req=0, transport=1, switch=0, callBack=0x814A8A10 Aug 12 12:52:25.370: //9/4C4349858016/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Aug 12 12:52:25.370: //9/4C4349858016/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0 Aug 12 12:52:25.370: //9/4C4349858016/SIP/Transport/sipTransportLogicSendMsg: Trying to send resp=0x88B01768 to default port=5060 Aug 12 12:52:25.370: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:10.30.0.2, rport:5060 with laddr:10.244.3.1 Aug 12 12:52:25.370: //9/4C4349858016/SIP/Transport/sipTransportLogicSendMsg: Connection obtained...sending msg=0x88B01768 Aug 12 12:52:25.370: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x88B01768, addr=10.30.0.2, port=5060, local_addr=10.244.3.1, connId=3 for UDP Aug 12 12:52:25.370: //9/4C4349858016/SIP/Info/sentErrResDisconnecting: Sent an 3456XX Error Response Aug 12 12:52:25.370: //9/4C4349858016/SIP/State/sipSPIChangeState: 0x889B18C8 : State change from (STATE_DISCONNECTING, SUBSTATE_NONE) to (STATE_DISCONNECTING, SUBSTATE_NONE) Aug 12 12:52:25.370: //9/4C4349858016/SIP/Media/sipSPIUpdateRtpSession: stun is disabled for stream:8A289CB0 Aug 12 12:52:25.370: //9/4C4349858016/SIP/Msg/ccsipDisplayMsg: Sent: SIP/2.0 504 Gateway Timeout Via: SIP/2.0/UDP 10.30.0.2:5060;branch=z9hG4bK-d8754z-d8c489750d22503d-1---d8754z-;rport From: "TESTE ANGOLA";tag=1f30f315 To: ;tag=52C41F8-1756 Call-ID: NjgyZTFkNzRkYWI4ZjBkZWVkODQ4MmFmMTQ4NGRmNWQ. CSeq: 1 INVITE Reason: Q.850;cause=102 Content-Length: 0 Aug 12 12:52:25.574: //9/4C4349858016/SIP/Info/ccsip_call_statistics: Requesting stats for callid=9 Aug 12 12:52:25.574: //9/4C4349858016/SIP/Info/ccsip_ipip_media_service_get_event_data: Event id = 26 Aug 12 12:52:25.574: //9/4C4349858016/SIP/Info/sipSPI_ipip_antiTrombone: Entered Antitrombone service Aug 12 12:52:25.574: //9/4C4349858016/SIP/Info/sipSPI_ipip_antiTrombone: Antitrombone service not configured Aug 12 12:52:25.574: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_DISCONNECT Aug 12 12:52:25.578: //9/4C4349858016/SIP/Info/ccsip_indicate_rt_packet_stats: Processing stats for callid=9, proc_id=1 Aug 12 12:52:25.578: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 8 Aug 12 12:52:25.578: //9/4C4349858016/SIP/Event/Session-Timer/sipSTSLMain: Event: E_STSL_SPI_EVENT Aug 12 12:52:25.578: //9/4C4349858016/SIP/Info/Session-Timer/sipSTSLMain: SE: 1800;refresher:none peer refresher:none, flags:2001, posted event:E_STSL_INVALID_PEER_EVENT, reason:4 Configured SE:1800, Configured Min-SE:1800 Aug 12 12:52:26.326: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [10.30.0.2]:5060, local_address:[10.244.3.1] Aug 12 12:52:26.326: //9/4C4349858016/SIP/Transport/sipSPISendErrorResponse: Sending ERROR Response to the transport layer Aug 12 12:52:26.326: //9/4C4349858016/SIP/Transport/sipSPITransportSendMessage: msg=0x8778526C, addr=10.30.0.2, port=5060, sentBy_port=5060, local_addr=10.244.3.1, is_req=0, transport=1, switch=0, callBack=0x0 Aug 12 12:52:26.326: //9/4C4349858016/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Aug 12 12:52:26.326: //9/4C4349858016/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0 Aug 12 12:52:26.326: //9/4C4349858016/SIP/Transport/sipTransportLogicSendMsg: Trying to send resp=0x8778526C to default port=5060 Aug 12 12:52:26.326: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:10.30.0.2, rport:5060 with laddr:10.244.3.1 Aug 12 12:52:26.326: //9/4C4349858016/SIP/Transport/sipTransportLogicSendMsg: Connection obtained...sending msg=0x8778526C Aug 12 12:52:26.326: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x8778526C, addr=10.30.0.2, port=5060, local_addr=10.244.3.1, connId=3 for UDP Aug 12 12:52:26.330: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Aug 12 12:52:26.330: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0 Aug 12 12:52:26.330: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: ACK sip:103@10.244.3.1;user=phone;transport=udp SIP/2.0 Via: SIP/2.0/UDP 10.30.0.2:5060;branch=z9hG4bK-d8754z-d8c489750d22503d-1---d8754z-;rport Max-Forwards: 70 To: ;tag=52C41F8-1756 From: "TESTE ANGOLA";tag=1f30f315 Call-ID: NjgyZTFkNzRkYWI4ZjBkZWVkODQ4MmFmMTQ4NGRmNWQ. CSeq: 1 ACK Content-Length: 0 Aug 12 12:52:26.330: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog Aug 12 12:52:26.330: //9/4C4349858016/SIP/Info/sipSPIFindCcbUASRespTable: *****CCB found in UAS Response table. ccb=0x889B18C8 Aug 12 12:52:26.330: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 10.30.0.2,Port 5060, Transport 1, SentBy Port 5060 Aug 12 12:52:26.330: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Converting TimeZone WAT to SIP default timezone = GMT Aug 12 12:52:26.330: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 10.30.0.2,Port 5060, Transport 1, SentBy Port 5060 Aug 12 12:52:26.330: //9/4C4349858016/SIP/Info/sipSPIIcpifUpdate: CallState: 2 Playout: 0 DiscTime:8680701 ConnTime 0 Aug 12 12:52:26.330: //9/4C4349858016/SIP/Media/sipSPIDestroyRtpSession: stream:8A289CB0 Aug 12 12:52:26.330: //9/4C4349858016/SIP/State/sipSPIChangeState: 0x889B18C8 : State change from (STATE_DISCONNECTING, SUBSTATE_NONE) to (STATE_DEAD, SUBSTATE_NONE) Aug 12 12:52:26.330: //9/4C4349858016/SIP/Call/sipSPICallInfo: The Call Setup Information is: Call Control Block (CCB) : 0x889B18C8 State of The Call : STATE_DEAD TCP Sockets Used : NO Calling Number : 726 Called Number : 103 Source IP Address (Sig ): 10.244.3.1 Destn SIP Req Addr:Port : 10.30.0.2:5060 Destn SIP Resp Addr:Port : 10.30.0.2:5060 Destination Name : 10.30.0.2 Aug 12 12:52:26.330: //9/4C4349858016/SIP/Call/sipSPIMediaCallInfo: Number of Media Streams: 1 Media Stream : 1 Negotiated Codec : g711ulaw Negotiated Codec Bytes : 160 Nego. Codec payload : 0 (tx), 0 (rx) Negotiated Dtmf-relay : 0 Dtmf-relay Payload : 0 (tx), 0 (rx) Source IP Address (Media): 10.244.3.1 Source IP Port (Media): 17758 Destn IP Address (Media): 10.30.0.7 Destn IP Port (Media): 39572 Orig Destn IP Address:Port (Media): [ - ]:0 Aug 12 12:52:26.330: //9/4C4349858016/SIP/Call/sipSPICallInfo: Disconnect Cause (CC) : 102 Disconnect Cause (SIP) : 504 Aug 12 12:52:26.330: //9/4C4349858016/SIP/Info/sipSPIUdeleteccCallIdFromTable: Removing call id 9 Aug 12 12:52:26.330: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDeleteContextFromTable: Context for key=[12] removed. Aug 12 12:52:26.330: //9/4C4349858016/SIP/Info/sipSPIUdeleteCcbFromUASReqTable: ****Deleting from UAS Request table. Aug 12 12:52:26.330: //9/4C4349858016/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x889B18C8 key=NjgyZTFkNzRkYWI4ZjBkZWVkODQ4MmFmMTQ4NGRmNWQ.103 Aug 12 12:52:26.330: //9/4C4349858016/SIP/Info/sipSPIUdeleteCcbFromUASRespTable: ****Deleting from UAS Response table. Aug 12 12:52:26.330: //9/4C4349858016/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x889B18C8 key=NjgyZTFkNzRkYWI4ZjBkZWVkODQ4MmFmMTQ4NGRmNWQ.52C41F8-1756 Aug 12 12:52:26.330: //9/4C4349858016/SIP/Info/sipSPIFlushEventBufferQueue: There are 1 events on the internal queue that are going to be free'd Aug 12 12:52:26.334: //9/4C4349858016/SIP/Info/sipSPI_ipip_free_codec_profile: Codec Profiles Freed Aug 12 12:52:26.334: //9/4C4349858016/SIP/Info/ccsip_offer_ans_delete: Aug 12 12:52:26.334: //9/4C4349858016/SIP/Info/ccsip_iwf_delete: Aug 12 12:52:26.334: //9/4C4349858016/SIP/Info/sipSPIUfreeOneCCB: Freeing ccb 889B18C8 Aug 12 12:52:26.334: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContextFromTable: NO context for key[12] Aug 12 12:52:26.342: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Sent: SIP/2.0 504 Gateway Timeout Via: SIP/2.0/UDP 10.30.0.2:5060;branch=z9hG4bK-d8754z-d8c489750d22503d-1---d8754z-;rport From: "TESTE ANGOLA";tag=1f30f315 To: ;tag=52C41F8-1756 Call-ID: NjgyZTFkNzRkYWI4ZjBkZWVkODQ4MmFmMTQ4NGRmNWQ. CSeq: 1 INVITE Reason: Q.850;cause=102 Content-Length: 0 Aug 12 12:52:26.890: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [10.30.0.2]:5060, local_address:[10.244.3.1] Aug 12 12:52:26.890: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Aug 12 12:52:26.890: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0 Aug 12 12:52:26.890: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: ACK sip:103@10.244.3.1;user=phone;transport=udp SIP/2.0 Via: SIP/2.0/UDP 10.30.0.2:5060;branch=z9hG4bK-d8754z-d8c489750d22503d-1---d8754z-;rport Max-Forwards: 70 To: ;tag=52C41F8-1756 From: "TESTE ANGOLA";tag=1f30f315 Call-ID: NjgyZTFkNzRkYWI4ZjBkZWVkODQ4MmFmMTQ4NGRmNWQ. CSeq: 1 ACK Content-Length: 0 Aug 12 12:52:26.894: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog Aug 12 12:52:26.894: //-1/xxxxxxxxxxxx/SIP/Error/sipSPISipIncomingMsg: Invalid method for (STATE_IDLE): ACK CMELDA001#