Hi,
I was wondering if anyone out there may be able to assist me in attempting to complete a SIP trunk to a Cisco Call Manager from an Avaya IP Office 500. So far, I am able to sucessfully call from any Avaya Phone on the IP Office to any extention on the CCM, but I cannot complete any calls from the CCM to the IPO 500. Here is a sample debug output from a failed call that looks like it should work to me. Have I overlooked anything?
*Sep 5 07:52:36.427: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 55
*Sep 5 07:52:36.427: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x00000000
*Sep 5 07:52:36.431: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessNewConnMsg: gConnTab=0x66250CC8, addr=10.10.240.1, port=36366, connid=2, transport=TCP
*Sep 5 07:52:36.431: //-1/xxxxxxxxxxxx/SIP/Transport/sipCreateConnInstance: Created new accptd conn=0x668C76C4, connid=2, addr=10.10.240.1, port=36366, transport=TCP
*Sep 5 07:52:36.431: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1
*Sep 5 07:52:36.431: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x00000000
*Sep 5 07:52:36.431: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessNewConnMsg: gConnTab=0x66250CC8, addr=10.10.240.1, port=36366, connid=2, transport=TCP
*Sep 5 07:52:36.431: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
INVITE sip:3349@10.10.30.193:5060 SIP/2.0
Date: Thu, 05 Sep 2013 08:18:43 GMT
Call-Info: <sip:10.10.240.1:5060>;method="NOTIFY;Event=telephone-event;Duration=500"
Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
From: "Majdi Sweis" <sip:2888@10.10.240.1>;tag=ed8670f9-bccc-48ab-a850-c066054d2648-50620776
Allow-Events: presence, kpml
P-Asserted-Identity: "Majdi Sweis" <sip:2888@10.10.240.1>
Supported: timer,resource-priority,replaces
Min-SE: 2000
Remote-Party-ID: "Majdi Sweis" <sip:2888@10.10.240.1>;party=calling;screen=yes;privacy=off
Content-Length: 0
User-Agent: Cisco-CUCM7.0
To: <sip:3349@10.10.30.193>
Contact: <sip:2888@10.10.240.1:5060;transport=tcp>
Expires: 180
Call-ID: c5be7900-22813e63-74ff7-1f00a0a@10.10.240.1
Via: SIP/2.0/TCP 10.10.240.1:5060;branch=z9hG4bK13e4c84f1f2adf
CSeq: 101 INVITE
Session-Expires: 2000
Max-Forwards: 70
*Sep 5 07:52:36.431: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog
*Sep 5 07:52:36.431: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAddContextToTable: Added context(0x6579676C) with key=[2] to table
*Sep 5 07:52:36.431: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 10.10.240.1,Port 36366, Transport 2, SentBy Port 5060
*Sep 5 07:52:36.431: //-1/F6CD57488007/SIP/State/sipSPIChangeState: 0x6579676C : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE)
*Sep 5 07:52:36.431: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 10.10.240.1,Port 36366, Transport 2, SentBy Port 5060
*Sep 5 07:52:36.431: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Clock Time Zone is UTC, same as GMT: Using GMT
*Sep 5 07:52:36.431: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 10.10.240.1,Port 36366, Transport 2, SentBy Port 5060
*Sep 5 07:52:36.435: //-1/F6CD57488007/SIP/Info/sipSPISetInfoFromRpid: Received current remote name: Majdi Sweis, current remote number: 2888
*Sep 5 07:52:36.435: //-1/F6CD57488007/SIP/Info/sipSPISetInfoFromRpid: Received ;screen=yes ;privacy=off -> Setting Octet3A 0x81, extended_privacy 0x00
*Sep 5 07:52:36.435: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentGTD: No GTD found in inbound container
*Sep 5 07:52:36.435: //-1/F6CD57488007/SIP/Info/sipSPIUaddCcbToUASReqTable: ****Adding to UAS Request table.
*Sep 5 07:52:36.435: //-1/F6CD57488007/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x6579676C key=c5be7900-22813e63-74ff7-1f00a0a@10.10.240.13349
*Sep 5 07:52:36.435: //-1/F6CD57488007/SIP/Info/sipSPIMatchSrcIpGroup: Match not found on carrier id
*Sep 5 07:52:36.435: //-1/F6CD57488007/SIP/Info/sipSPIMatchSrcIpGroup: Match not found on Incoming called number: 3349
*Sep 5 07:52:36.435: //-1/F6CD57488007/SIP/Info/sipSPIMatchSrcIpGroup: Match not found on destination pattern: 2888
*Sep 5 07:52:36.435: //-1/F6CD57488007/SIP/Info/ccsipUpdateIncomingCallParams: ccCallInfo: Calling name Majdi Sweis, number 2888, Calling oct3 0x00, oct_3a 0x81, Called number 3349
*Sep 5 07:52:36.439: ccDumpTdRequestDataSip:
*Sep 5 07:52:36.439: reqURI=sip:3349@10.10.30.193:5060
*Sep 5 07:52:36.439: calling_urip=sip:2888@10.10.240.1
*Sep 5 07:52:36.439: url_dump_header_line_avpair:
*Sep 5 07:52:36.439: num_headers = 19
*Sep 5 07:52:36.439: headers[0].linep = Date:Thu, 05 Sep 2013 08:18:43 GMT, len = 34
*Sep 5 07:52:36.439: data.attr.datap = Date:Thu, 05 Sep 2013 08:18:43 GMT, len = 4
*Sep 5 07:52:36.439: data.value.datap = Thu, 05 Sep 2013 08:18:43 GMT, len = 29
*Sep 5 07:52:36.439: headers[1].linep = Call-Info:<sip:10.10.240.1:5060>;method="NOTIFY;Event=telephone-event;Duration=500", len = 83
*Sep 5 07:52:36.439: data.attr.datap = Call-Info:<sip:10.10.240.1:5060>;method="NOTIFY;Event=telephone-event;Duration=500", len = 9
*Sep 5 07:52:36.439: data.value.datap = <sip:10.10.240.1:5060>;method="NOTIFY;Event=telephone-event;Duration=500", len = 73
*Sep 5 07:52:36.439: headers[2].linep = Allow:INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, len = 86
*Sep 5 07:52:36.439: data.attr.datap = Allow:INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, len = 5
*Sep 5 07:52:36.439: data.value.datap = INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, len = 80
*Sep 5 07:52:36.439: headers[3].linep = From:"Majdi Sweis" <sip:2888@10.10.240.1>;tag=ed8670f9-bccc-48ab-a850-c066054d2648-50620776, len = 91
*Sep 5 07:52:36.439: data.attr.datap = From:"Majdi Sweis" <sip:2888@10.10.240.1>;tag=ed8670f9-bccc-48ab-a850-c066054d2648-50620776, len = 4
*Sep 5 07:52:36.439: data.value.datap = "Majdi Sweis" <sip:2888@10.10.240.1>;tag=ed8670f9-bccc-48ab-a850-c066054d2648-50620776, len = 86
*Sep 5 07:52:36.439: headers[4].linep = Allow-Events
resence, kpml, len = 27
*Sep 5 07:52:36.439: data.attr.datap = Allow-Eventsresence, kpml, len = 12
*Sep 5 07:52:36.439: data.value.datap = presence, kpml, len = 14
*Sep 5 07:52:36.439: headers[5].linep = P-Asserted-Identity:"Majdi Sweis" <sip:2888@10.10.240.1>, len = 56
*Sep 5 07:52:36.439: data.attr.datap = P-Asserted-Identity:"Majdi Sweis" <sip:2888@10.10.240.1>, len = 19
*Sep 5 07:52:36.439: data.value.datap = "Majdi Sweis" <sip:2888@10.10.240.1>, len = 36
*Sep 5 07:52:36.439: headers[6].linep = Supported:timer,resource-priority,replaces, len = 42
*Sep 5 07:52:36.439: data.attr.datap = Supported:timer,resource-priority,replaces, len = 9
*Sep 5 07:52:36.443: data.value.datap = timer,resource-priority,replaces, len = 32
*Sep 5 07:52:36.443: headers[7].linep = Min-SE:2000, len = 11
*Sep 5 07:52:36.443: data.attr.datap = Min-SE:2000, len = 6
*Sep 5 07:52:36.443: data.value.datap = 2000, len = 4
*Sep 5 07:52:36.443: headers[8].linep = Remote-Party-ID:"Majdi Sweis" <sip:2888@10.10.240.1>;party=calling;screen=yes;privacy=off, len = 89
*Sep 5 07:52:36.443: data.attr.datap = Remote-Party-ID:"Majdi Sweis" <sip:2888@10.10.240.1>;party=calling;screen=yes;privacy=off, len = 15
*Sep 5 07:52:36.443: data.value.datap = "Majdi Sweis" <sip:2888@10.10.240.1>;party=calling;screen=yes;privacy=off, len = 73
*Sep 5 07:52:36.443: headers[9].linep = Content-Length:0, len = 16
*Sep 5 07:52:36.443: data.attr.datap = Content-Length:0, len = 14
*Sep 5 07:52:36.443: data.value.datap = 0, len = 1
*Sep 5 07:52:36.443: headers[10].linep = User-Agent:Cisco-CUCM7.0, len = 24
*Sep 5 07:52:36.443: data.attr.datap = User-Agent:Cisco-CUCM7.0, len = 10
*Sep 5 07:52:36.443: data.value.datap = Cisco-CUCM7.0, len = 13
*Sep 5 07:52:36.443: headers[11].linep = To:<sip:3349@10.10.30.193>, len = 26
*Sep 5 07:52:36.443: data.attr.datap = To:<sip:3349@10.10.30.193>, len = 2
*Sep 5 07:52:36.443: data.value.datap = <sip:3349@10.10.30.193>, len = 23
*Sep 5 07:52:36.443: headers[12].linep = Contact:<sip:2888@10.10.240.1:5060;transport=tcp>, len = 49
*Sep 5 07:52:36.443: data.attr.datap = Contact:<sip:2888@10.10.240.1:5060;transport=tcp>, len = 7
*Sep 5 07:52:36.443: data.value.datap = <sip:2888@10.10.240.1:5060;transport=tcp>, len = 41
*Sep 5 07:52:36.443: headers[13].linep = Expires:180, len = 11
*Sep 5 07:52:36.443: data.attr.datap = Expires:180, len = 7
*Sep 5 07:52:36.443: data.value.datap = 180, len = 3
*Sep 5 07:52:36.443: headers[14].linep = Call-ID:c5be7900-22813e63-74ff7-1f00a0a@10.10.240.1, len = 51
*Sep 5 07:52:36.443: data.attr.datap = Call-ID:c5be7900-22813e63-74ff7-1f00a0a@10.10.240.1, len = 7
*Sep 5 07:52:36.443: data.value.datap = c5be7900-22813e63-74ff7-1f00a0a@10.10.240.1, len = 43
*Sep 5 07:52:36.443: headers[15].linep = Via:SIP/2.0/TCP 10.10.240.1:5060;branch=z9hG4bK13e4c84f1f2adf, len = 61
*Sep 5 07:52:36.443: data.attr.datap = Via:SIP/2.0/TCP 10.10.240.1:5060;branch=z9hG4bK13e4c84f1f2adf, len = 3
*Sep 5 07:52:36.443: data.value.datap = SIP/2.0/TCP 10.10.240.1:5060;branch=z9hG4bK13e4c84f1f2adf, len = 57
*Sep 5 07:52:36.443: headers[16].linep = CSeq:101 INVITE, len = 15
*Sep 5 07:52:36.443: data.attr.datap = CSeq:101 INVITE, len = 4
*Sep 5 07:52:36.443: data.value.datap = 101 INVITE, len = 10
*Sep 5 07:52:36.443: headers[17].linep = Session-Expires:2000, len = 20
*Sep 5 07:52:36.443: data.attr.datap = Session-Expires:2000, len = 15
*Sep 5 07:52:36.443: data.value.datap = 2000, len = 4
*Sep 5 07:52:36.443: headers[18].linep = Max-Forwards:70, len = 15
*Sep 5 07:52:36.443: data.attr.datap = Max-Forwards:70, len = 12
*Sep 5 07:52:36.443: data.value.datap = 70, len = 2num_bodies = 0
*Sep 5 07:52:36.443: //-1/F6CD57488007/SIP/Info/sipSPIGetShrlPeer: Try match incoming dialpeer for Calling number: : 2888
*Sep 5 07:52:36.443: //-1/F6CD57488007/SIP/Info/sipSPIGetCallConfig: Peer tag 1 matched for incoming call
*Sep 5 07:52:36.443: //-1/F6CD57488007/SIP/Info/sipSPIGetCallConfig: Precondition tag absent in Require/Supported header
*Sep 5 07:52:36.447: //-1/F6CD57488007/SIP/Info/sipSPIGetCallConfig: Not using Voice Class Codec
*Sep 5 07:52:36.447: //-1/F6CD57488007/SIP/Media/sipSPICopyPeerDataToCCB: Firewall traversal is not enabled
*Sep 5 07:52:36.447: //-1/F6CD57488007/SIP/Info/sipSPIGetCallConfig: xcoder high-density disabled
*Sep 5 07:52:36.447: //-1/F6CD57488007/SIP/Info/sipSPIGetCallConfig: Flow Mode set to FLOW_THROUGH
*Sep 5 07:52:36.447: //-1/F6CD57488007/SIP/Info/sipSPIContinueNewMsgInvite: Calling name Majdi Sweis, number 2888, Calling oct3 0x00, oct_3a 0x81, ext_priv 0x00, Called number 3349, oct3 0x00
*Sep 5 07:52:36.447: //-1/F6CD57488007/SIP/Info/sipSPIContinueNewMsgInvite: Carrier id code , prev_cid NONE, next_cid NONE, prev_tgrp NONE, next_tgrp NONE
*Sep 5 07:52:36.447: //-1/F6CD57488007/SIP/Info/sipSPIRscmsmAvail: Value returned by check is = 0
*Sep 5 07:52:36.447: //2/F6CD57488007/SIP/Info/sipSPINegotiateSessionExpires: Min-SE Header: 2000
*Sep 5 07:52:36.447: //2/F6CD57488007/SIP/Info/sipSPINegotiateSessionExpires:
Session-Expires value: 2000 refresher: 3
*Sep 5 07:52:36.447: //2/F6CD57488007/SIP/Info/sipSPI_ipip_Add_SessionExpiresParamsToContainer: Session-refresh parameters added to container minse = 2000 session expire = 2000 refresher = 3
*Sep 5 07:52:36.447: //2/F6CD57488007/SIP/Info/sipSPIProcessHistoryInfoHeader: No HI headers recvd from app container
*Sep 5 07:52:36.447: //2/F6CD57488007/SIP/Info/sipSPIProcessDiversionHeader: No diversion headers recvd from app container
*Sep 5 07:52:36.447: //2/F6CD57488007/SIP/Info/sipSPIProcessNotifyCallInfoHeader: Callinfo parsed - Destination url = <sip:10.10.240.1:5060>, duration = 500
*Sep 5 07:52:36.447: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentSDP: No SDP found in inbound container
*Sep 5 07:52:36.447: //2/F6CD57488007/SIP/Info/sipSPIDoQoSNegotiationWithNoMediaLine: Entry
*Sep 5 07:52:36.447: //2/F6CD57488007/SIP/Info/sipSPIDoQoSNegotiationWithNoMediaLine: Local Precondition: 1, Remote Precondition: 1
*Sep 5 07:52:36.447: //2/F6CD57488007/SIP/Info/sipSPICanSetFallbackFlag: Local Fallback is not active
*Sep 5 07:52:36.447: //2/F6CD57488007/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo:
CallID 2, sdp 0x6708B010 channels 0x657979E0
*Sep 5 07:52:36.447: //2/F6CD57488007/SIP/Info/copy_channels:
callId 2 size 0 ptr 0x65A299CC)
*Sep 5 07:52:36.447: //2/F6CD57488007/SIP/Info/sipSPIUpdateSrcSdpFixedPart: Delayed media case...creating new stream
*Sep 5 07:52:36.447: //2/F6CD57488007/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 10.10.30.193
*Sep 5 07:52:36.447: //-1/xxxxxxxxxxxx/SIP/Media/sipSPIReserveRtpPort: reserved port 18648 for stream 1
*Sep 5 07:52:36.447: //2/F6CD57488007/SIP/Info/sipSPIUpdateSrcSdpFixedPart: Reserving rtp port for stream 1, src_port=18648
*Sep 5 07:52:36.451: //2/F6CD57488007/SIP/Media/sipSPIAddSDPMediaPayload: Preferred method of dtmf relay is: 6, with payload: 101
*Sep 5 07:52:36.451: //-1/xxxxxxxxxxxx/SIP/Info/convert_codec_bytes_to_ptime: Values :Codec: g711ulaw codecbytes :160, ptime: 20
*Sep 5 07:52:36.451: //2/F6CD57488007/SIP/Info/sipSPIAddBillingInfoToCcb: sipCallId for billing records = c5be7900-22813e63-74ff7-1f00a0a@10.10.240.1
*Sep 5 07:52:36.451: //2/F6CD57488007/SIP/Info/sipSPI_ipip_store_channel_info: Store channelInfo in CallInfo
*Sep 5 07:52:36.451: //2/F6CD57488007/SIP/Info/sipSPI_ipip_store_channel_info: negotiated dtmf not available, using dialpeer config dtmf = 6
*Sep 5 07:52:36.451: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentQSIG: No QSIG Body found in inbound container
*Sep 5 07:52:36.451: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentQ931: No RawMsg Body found in inbound container
*Sep 5 07:52:36.451: //-1/xxxxxxxxxxxx/SIP/Info/sipSPICreateNewRawMsg: No Data to form The Raw Message
*Sep 5 07:52:36.451: //2/F6CD57488007/SIP/Info/ccsip_set_bearer_capability:
Bearer Capability: Speech (0x00)
*Sep 5 07:52:36.451: //2/F6CD57488007/SIP/Info/sipSPIContinueNewMsgInvite: ccsip_api_call_setup_ind returned: SIP_SUCCESS_DELAYED_MEDIA
*Sep 5 07:52:36.451: //2/F6CD57488007/SIP/Info/sipSPIUaddccCallIdToTable: Adding call id 2 to table
*Sep 5 07:52:36.455: //2/F6CD57488007/SIP/Transport/sipSPITransportSendMessage: msg=0x67073554, addr=10.10.240.1, port=36366, sentBy_port=5060, is_req=0, transport=2, switch=0, callBack=0x00000000
*Sep 5 07:52:36.455: //2/F6CD57488007/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
*Sep 5 07:52:36.455: //2/F6CD57488007/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0
*Sep 5 07:52:36.455: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x67073554, addr=10.10.240.1, port=36366, connId=2 for TCP
*Sep 5 07:52:36.455: //2/F6CD57488007/SIP/State/sipSPIChangeState: 0x6579676C : State change from (STATE_IDLE, SUBSTATE_NONE) to (STATE_RECD_INVITE, SUBSTATE_NONE)
*Sep 5 07:52:36.455: //2/F6CD57488007/SIP/Info/sipSPIProcessContactInfo: Previous Hop 10.10.240.1:5060
*Sep 5 07:52:36.459: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 100 Trying
Via: SIP/2.0/TCP 10.10.240.1:5060;branch=z9hG4bK13e4c84f1f2adf
From: "Majdi Sweis" <sip:2888@10.10.240.1>;tag=ed8670f9-bccc-48ab-a850-c066054d2648-50620776
To: <sip:3349@10.10.30.193>
Date: Thu, 05 Sep 2013 07:52:36 GMT
Call-ID: c5be7900-22813e63-74ff7-1f00a0a@10.10.240.1
CSeq: 101 INVITE
Allow-Events: telephone-event
Server: Cisco-SIPGateway/IOS-12.x
Content-Length: 0
*Sep 5 07:52:36.459: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_PROCEEDING
*Sep 5 07:52:36.463: //2/F6CD57488007/SIP/Info/ccsip_call_statistics: Stats are not supported for IPIP call.
*Sep 5 07:52:36.463: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_DISCONNECT
*Sep 5 07:52:36.463: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 3
*Sep 5 07:52:36.463: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 7
*Sep 5 07:52:36.463: //2/F6CD57488007/SIP/Info/act_recdinvite_disconnect: Performing disconnect
*Sep 5 07:52:36.463: //2/F6CD57488007/SIP/Info/sipSPIUaddCcbToUASRespTable: ****Adding to UAS Response table.
*Sep 5 07:52:36.463: //2/F6CD57488007/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x6579676C key=c5be7900-22813e63-74ff7-1f00a0a@10.10.240.1488070-A6F
*Sep 5 07:52:36.467: //2/F6CD57488007/SIP/Info/sipSPISendInviteResponse: Associated container=0x657D5C04 to Invite Response 404
*Sep 5 07:52:36.467: //2/F6CD57488007/SIP/Transport/sipSPITransportSendMessage: msg=0x670507D0, addr=10.10.240.1, port=36366, sentBy_port=5060, is_req=0, transport=2, switch=0, callBack=0x6131C2BC
*Sep 5 07:52:36.467: //2/F6CD57488007/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
*Sep 5 07:52:36.467: //2/F6CD57488007/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0
*Sep 5 07:52:36.467: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x670507D0, addr=10.10.240.1, port=36366, connId=2 for TCP
*Sep 5 07:52:36.467: //2/F6CD57488007/SIP/Info/sentErrResDisconnecting: Sent an 3456XX Error Response
*Sep 5 07:52:36.467: //2/F6CD57488007/SIP/State/sipSPIChangeState: 0x6579676C : State change from (STATE_RECD_INVITE, SUBSTATE_NONE) to (STATE_DISCONNECTING, SUBSTATE_NONE)
*Sep 5 07:52:36.467: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 404 Not Found
Via: SIP/2.0/TCP 10.10.240.1:5060;branch=z9hG4bK13e4c84f1f2adf
From: "Majdi Sweis" <sip:2888@10.10.240.1>;tag=ed8670f9-bccc-48ab-a850-c066054d2648-50620776
To: <sip:3349@10.10.30.193>;tag=488070-A6F
Date: Thu, 05 Sep 2013 07:52:36 GMT
Call-ID: c5be7900-22813e63-74ff7-1f00a0a@10.10.240.1
CSeq: 101 INVITE
Allow-Events: telephone-event
Server: Cisco-SIPGateway/IOS-12.x
Reason: Q.850;cause=1
Content-Length: 0
*Sep 5 07:52:36.471: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1
*Sep 5 07:52:36.471: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x00000000
*Sep 5 07:52:36.471: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessNewConnMsg: gConnTab=0x66250CC8, addr=10.10.240.1, port=36366, connid=2, transport=TCP
*Sep 5 07:52:36.471: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
ACK sip:3349@10.10.30.193:5060 SIP/2.0
Date: Thu, 05 Sep 2013 08:18:43 GMT
From: "Majdi Sweis" <sip:2888@10.10.240.1>;tag=ed8670f9-bccc-48ab-a850-c066054d2648-50620776
Allow-Events: presence, kpml
Content-Length: 0
To: <sip:3349@10.10.30.193>;tag=488070-A6F
Call-ID: c5be7900-22813e63-74ff7-1f00a0a@10.10.240.1
Via: SIP/2.0/TCP 10.10.240.1:5060;branch=z9hG4bK13e4c84f1f2adf
CSeq: 101 ACK
Max-Forwards: 70
*Sep 5 07:52:36.471: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog
*Sep 5 07:52:36.475: //2/F6CD57488007/SIP/Info/sipSPIFindCcbUASRespTable: *****CCB found in UAS Response table. ccb=0x6579676C
*Sep 5 07:52:36.475: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 10.10.240.1,Port 36366, Transport 2, SentBy Port 5060
*Sep 5 07:52:36.475: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Clock Time Zone is UTC, same as GMT: Using GMT
*Sep 5 07:52:36.475: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 10.10.240.1,Port 36366, Transport 2, SentBy Port 5060
*Sep 5 07:52:36.475: //2/F6CD57488007/SIP/Info/sipSPIIcpifUpdate: CallState: 2 Playout: 0 DiscTime:475148 ConnTime 0
*Sep 5 07:52:36.475: //2/F6CD57488007/SIP/State/sipSPIChangeState: 0x6579676C : State change from (STATE_DISCONNECTING, SUBSTATE_NONE) to (STATE_DEAD, SUBSTATE_NONE)
*Sep 5 07:52:36.475: //2/F6CD57488007/SIP/Call/sipSPICallInfo:
The Call Setup Information is:
Call Control Block (CCB) : 0x6579676C
State of The Call : STATE_DEAD
TCP Sockets Used : YES
Calling Number : 2888
Called Number : 3349
Source IP Address (Sig ): 10.10.30.193
Destn SIP Req Addrort : 10.10.240.1:5060
Destn SIP Resp Addrort : 10.10.240.1:36366
Destination Name : 10.10.240.1
*Sep 5 07:52:36.475: //2/F6CD57488007/SIP/Call/sipSPIMediaCallInfo:
Number of Media Streams: 1
Media Stream : 1
Negotiated Codec : No Codec
Negotiated Codec Bytes : 0
Nego. Codec payload : 255 (tx), 255 (rx)
Negotiated Dtmf-relay : 0
Dtmf-relay Payload : 0 (tx), 0 (rx)
Source IP Address (Media): 10.10.30.193
Source IP Port (Media): 18648
Destn IP Address (Media): -
Destn IP Port (Media): 0
Orig Destn IP Addressort (Media): [ - ]:0
*Sep 5 07:52:36.475: //2/F6CD57488007/SIP/Call/sipSPICallInfo:
Disconnect Cause (CC) : 1
Disconnect Cause (SIP) : 404
*Sep 5 07:52:36.475: //2/F6CD57488007/SIP/Info/sipSPIUdeleteccCallIdFromTable: Removing call id 2
*Sep 5 07:52:36.475: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDeleteContextFromTable: Context for key=[2] removed.
*Sep 5 07:52:36.479: //2/F6CD57488007/SIP/Info/sipSPIUdeleteCcbFromUASReqTable: ****Deleting from UAS Request table.
*Sep 5 07:52:36.479: //2/F6CD57488007/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x6579676C key=c5be7900-22813e63-74ff7-1f00a0a@10.10.240.13349
*Sep 5 07:52:36.479: //2/F6CD57488007/SIP/Info/sipSPIUdeleteCcbFromUASRespTable: ****Deleting from UAS Response table.
*Sep 5 07:52:36.479: //2/F6CD57488007/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x6579676C key=c5be7900-22813e63-74ff7-1f00a0a@10.10.240.1488070-A6F
*Sep 5 07:52:36.479: //2/F6CD57488007/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd
*Sep 5 07:52:36.479: //2/F6CD57488007/SIP/Info/ccsip_qos_cleanup: Entry
*Sep 5 07:52:36.479: //2/F6CD57488007/SIP/Info/sipSPI_ipip_free_codec_profile: Codec Profiles Freed
*Sep 5 07:52:36.479: //2/F6CD57488007/SIP/Info/sipSPIUfreeOneCCB: Freeing ccb 6579676C
*Sep 5 07:52:36.479: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContextFromTable: NO context for key[2]
*Sep 5 07:52:56.055: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceHandleConnAgeing: Holder=0x6701BEE4 Connection=0x668C76C4, addr=0.0.0.1, port=168488961, connid=0 has been REFRESHED
*Sep 5 07:52:56.055: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportSetAgeingTimer: Aging timer initiated for holder=0x6701BEE4,addr=10.10.240.1
Router#
Router#
Router#
I am pretty certain that the 404 not found error is the problem, but I am unsure as to whether or not that is the fault of the CCM or the IPO 500. Any help would be greatly appreciated. Thanks!!!
I was wondering if anyone out there may be able to assist me in attempting to complete a SIP trunk to a Cisco Call Manager from an Avaya IP Office 500. So far, I am able to sucessfully call from any Avaya Phone on the IP Office to any extention on the CCM, but I cannot complete any calls from the CCM to the IPO 500. Here is a sample debug output from a failed call that looks like it should work to me. Have I overlooked anything?
*Sep 5 07:52:36.427: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 55
*Sep 5 07:52:36.427: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x00000000
*Sep 5 07:52:36.431: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessNewConnMsg: gConnTab=0x66250CC8, addr=10.10.240.1, port=36366, connid=2, transport=TCP
*Sep 5 07:52:36.431: //-1/xxxxxxxxxxxx/SIP/Transport/sipCreateConnInstance: Created new accptd conn=0x668C76C4, connid=2, addr=10.10.240.1, port=36366, transport=TCP
*Sep 5 07:52:36.431: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1
*Sep 5 07:52:36.431: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x00000000
*Sep 5 07:52:36.431: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessNewConnMsg: gConnTab=0x66250CC8, addr=10.10.240.1, port=36366, connid=2, transport=TCP
*Sep 5 07:52:36.431: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
INVITE sip:3349@10.10.30.193:5060 SIP/2.0
Date: Thu, 05 Sep 2013 08:18:43 GMT
Call-Info: <sip:10.10.240.1:5060>;method="NOTIFY;Event=telephone-event;Duration=500"
Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
From: "Majdi Sweis" <sip:2888@10.10.240.1>;tag=ed8670f9-bccc-48ab-a850-c066054d2648-50620776
Allow-Events: presence, kpml
P-Asserted-Identity: "Majdi Sweis" <sip:2888@10.10.240.1>
Supported: timer,resource-priority,replaces
Min-SE: 2000
Remote-Party-ID: "Majdi Sweis" <sip:2888@10.10.240.1>;party=calling;screen=yes;privacy=off
Content-Length: 0
User-Agent: Cisco-CUCM7.0
To: <sip:3349@10.10.30.193>
Contact: <sip:2888@10.10.240.1:5060;transport=tcp>
Expires: 180
Call-ID: c5be7900-22813e63-74ff7-1f00a0a@10.10.240.1
Via: SIP/2.0/TCP 10.10.240.1:5060;branch=z9hG4bK13e4c84f1f2adf
CSeq: 101 INVITE
Session-Expires: 2000
Max-Forwards: 70
*Sep 5 07:52:36.431: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog
*Sep 5 07:52:36.431: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAddContextToTable: Added context(0x6579676C) with key=[2] to table
*Sep 5 07:52:36.431: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 10.10.240.1,Port 36366, Transport 2, SentBy Port 5060
*Sep 5 07:52:36.431: //-1/F6CD57488007/SIP/State/sipSPIChangeState: 0x6579676C : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE)
*Sep 5 07:52:36.431: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 10.10.240.1,Port 36366, Transport 2, SentBy Port 5060
*Sep 5 07:52:36.431: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Clock Time Zone is UTC, same as GMT: Using GMT
*Sep 5 07:52:36.431: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 10.10.240.1,Port 36366, Transport 2, SentBy Port 5060
*Sep 5 07:52:36.435: //-1/F6CD57488007/SIP/Info/sipSPISetInfoFromRpid: Received current remote name: Majdi Sweis, current remote number: 2888
*Sep 5 07:52:36.435: //-1/F6CD57488007/SIP/Info/sipSPISetInfoFromRpid: Received ;screen=yes ;privacy=off -> Setting Octet3A 0x81, extended_privacy 0x00
*Sep 5 07:52:36.435: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentGTD: No GTD found in inbound container
*Sep 5 07:52:36.435: //-1/F6CD57488007/SIP/Info/sipSPIUaddCcbToUASReqTable: ****Adding to UAS Request table.
*Sep 5 07:52:36.435: //-1/F6CD57488007/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x6579676C key=c5be7900-22813e63-74ff7-1f00a0a@10.10.240.13349
*Sep 5 07:52:36.435: //-1/F6CD57488007/SIP/Info/sipSPIMatchSrcIpGroup: Match not found on carrier id
*Sep 5 07:52:36.435: //-1/F6CD57488007/SIP/Info/sipSPIMatchSrcIpGroup: Match not found on Incoming called number: 3349
*Sep 5 07:52:36.435: //-1/F6CD57488007/SIP/Info/sipSPIMatchSrcIpGroup: Match not found on destination pattern: 2888
*Sep 5 07:52:36.435: //-1/F6CD57488007/SIP/Info/ccsipUpdateIncomingCallParams: ccCallInfo: Calling name Majdi Sweis, number 2888, Calling oct3 0x00, oct_3a 0x81, Called number 3349
*Sep 5 07:52:36.439: ccDumpTdRequestDataSip:
*Sep 5 07:52:36.439: reqURI=sip:3349@10.10.30.193:5060
*Sep 5 07:52:36.439: calling_urip=sip:2888@10.10.240.1
*Sep 5 07:52:36.439: url_dump_header_line_avpair:
*Sep 5 07:52:36.439: num_headers = 19
*Sep 5 07:52:36.439: headers[0].linep = Date:Thu, 05 Sep 2013 08:18:43 GMT, len = 34
*Sep 5 07:52:36.439: data.attr.datap = Date:Thu, 05 Sep 2013 08:18:43 GMT, len = 4
*Sep 5 07:52:36.439: data.value.datap = Thu, 05 Sep 2013 08:18:43 GMT, len = 29
*Sep 5 07:52:36.439: headers[1].linep = Call-Info:<sip:10.10.240.1:5060>;method="NOTIFY;Event=telephone-event;Duration=500", len = 83
*Sep 5 07:52:36.439: data.attr.datap = Call-Info:<sip:10.10.240.1:5060>;method="NOTIFY;Event=telephone-event;Duration=500", len = 9
*Sep 5 07:52:36.439: data.value.datap = <sip:10.10.240.1:5060>;method="NOTIFY;Event=telephone-event;Duration=500", len = 73
*Sep 5 07:52:36.439: headers[2].linep = Allow:INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, len = 86
*Sep 5 07:52:36.439: data.attr.datap = Allow:INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, len = 5
*Sep 5 07:52:36.439: data.value.datap = INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, len = 80
*Sep 5 07:52:36.439: headers[3].linep = From:"Majdi Sweis" <sip:2888@10.10.240.1>;tag=ed8670f9-bccc-48ab-a850-c066054d2648-50620776, len = 91
*Sep 5 07:52:36.439: data.attr.datap = From:"Majdi Sweis" <sip:2888@10.10.240.1>;tag=ed8670f9-bccc-48ab-a850-c066054d2648-50620776, len = 4
*Sep 5 07:52:36.439: data.value.datap = "Majdi Sweis" <sip:2888@10.10.240.1>;tag=ed8670f9-bccc-48ab-a850-c066054d2648-50620776, len = 86
*Sep 5 07:52:36.439: headers[4].linep = Allow-Events
resence, kpml, len = 27*Sep 5 07:52:36.439: data.attr.datap = Allow-Events
resence, kpml, len = 12*Sep 5 07:52:36.439: data.value.datap = presence, kpml, len = 14
*Sep 5 07:52:36.439: headers[5].linep = P-Asserted-Identity:"Majdi Sweis" <sip:2888@10.10.240.1>, len = 56
*Sep 5 07:52:36.439: data.attr.datap = P-Asserted-Identity:"Majdi Sweis" <sip:2888@10.10.240.1>, len = 19
*Sep 5 07:52:36.439: data.value.datap = "Majdi Sweis" <sip:2888@10.10.240.1>, len = 36
*Sep 5 07:52:36.439: headers[6].linep = Supported:timer,resource-priority,replaces, len = 42
*Sep 5 07:52:36.439: data.attr.datap = Supported:timer,resource-priority,replaces, len = 9
*Sep 5 07:52:36.443: data.value.datap = timer,resource-priority,replaces, len = 32
*Sep 5 07:52:36.443: headers[7].linep = Min-SE:2000, len = 11
*Sep 5 07:52:36.443: data.attr.datap = Min-SE:2000, len = 6
*Sep 5 07:52:36.443: data.value.datap = 2000, len = 4
*Sep 5 07:52:36.443: headers[8].linep = Remote-Party-ID:"Majdi Sweis" <sip:2888@10.10.240.1>;party=calling;screen=yes;privacy=off, len = 89
*Sep 5 07:52:36.443: data.attr.datap = Remote-Party-ID:"Majdi Sweis" <sip:2888@10.10.240.1>;party=calling;screen=yes;privacy=off, len = 15
*Sep 5 07:52:36.443: data.value.datap = "Majdi Sweis" <sip:2888@10.10.240.1>;party=calling;screen=yes;privacy=off, len = 73
*Sep 5 07:52:36.443: headers[9].linep = Content-Length:0, len = 16
*Sep 5 07:52:36.443: data.attr.datap = Content-Length:0, len = 14
*Sep 5 07:52:36.443: data.value.datap = 0, len = 1
*Sep 5 07:52:36.443: headers[10].linep = User-Agent:Cisco-CUCM7.0, len = 24
*Sep 5 07:52:36.443: data.attr.datap = User-Agent:Cisco-CUCM7.0, len = 10
*Sep 5 07:52:36.443: data.value.datap = Cisco-CUCM7.0, len = 13
*Sep 5 07:52:36.443: headers[11].linep = To:<sip:3349@10.10.30.193>, len = 26
*Sep 5 07:52:36.443: data.attr.datap = To:<sip:3349@10.10.30.193>, len = 2
*Sep 5 07:52:36.443: data.value.datap = <sip:3349@10.10.30.193>, len = 23
*Sep 5 07:52:36.443: headers[12].linep = Contact:<sip:2888@10.10.240.1:5060;transport=tcp>, len = 49
*Sep 5 07:52:36.443: data.attr.datap = Contact:<sip:2888@10.10.240.1:5060;transport=tcp>, len = 7
*Sep 5 07:52:36.443: data.value.datap = <sip:2888@10.10.240.1:5060;transport=tcp>, len = 41
*Sep 5 07:52:36.443: headers[13].linep = Expires:180, len = 11
*Sep 5 07:52:36.443: data.attr.datap = Expires:180, len = 7
*Sep 5 07:52:36.443: data.value.datap = 180, len = 3
*Sep 5 07:52:36.443: headers[14].linep = Call-ID:c5be7900-22813e63-74ff7-1f00a0a@10.10.240.1, len = 51
*Sep 5 07:52:36.443: data.attr.datap = Call-ID:c5be7900-22813e63-74ff7-1f00a0a@10.10.240.1, len = 7
*Sep 5 07:52:36.443: data.value.datap = c5be7900-22813e63-74ff7-1f00a0a@10.10.240.1, len = 43
*Sep 5 07:52:36.443: headers[15].linep = Via:SIP/2.0/TCP 10.10.240.1:5060;branch=z9hG4bK13e4c84f1f2adf, len = 61
*Sep 5 07:52:36.443: data.attr.datap = Via:SIP/2.0/TCP 10.10.240.1:5060;branch=z9hG4bK13e4c84f1f2adf, len = 3
*Sep 5 07:52:36.443: data.value.datap = SIP/2.0/TCP 10.10.240.1:5060;branch=z9hG4bK13e4c84f1f2adf, len = 57
*Sep 5 07:52:36.443: headers[16].linep = CSeq:101 INVITE, len = 15
*Sep 5 07:52:36.443: data.attr.datap = CSeq:101 INVITE, len = 4
*Sep 5 07:52:36.443: data.value.datap = 101 INVITE, len = 10
*Sep 5 07:52:36.443: headers[17].linep = Session-Expires:2000, len = 20
*Sep 5 07:52:36.443: data.attr.datap = Session-Expires:2000, len = 15
*Sep 5 07:52:36.443: data.value.datap = 2000, len = 4
*Sep 5 07:52:36.443: headers[18].linep = Max-Forwards:70, len = 15
*Sep 5 07:52:36.443: data.attr.datap = Max-Forwards:70, len = 12
*Sep 5 07:52:36.443: data.value.datap = 70, len = 2num_bodies = 0
*Sep 5 07:52:36.443: //-1/F6CD57488007/SIP/Info/sipSPIGetShrlPeer: Try match incoming dialpeer for Calling number: : 2888
*Sep 5 07:52:36.443: //-1/F6CD57488007/SIP/Info/sipSPIGetCallConfig: Peer tag 1 matched for incoming call
*Sep 5 07:52:36.443: //-1/F6CD57488007/SIP/Info/sipSPIGetCallConfig: Precondition tag absent in Require/Supported header
*Sep 5 07:52:36.447: //-1/F6CD57488007/SIP/Info/sipSPIGetCallConfig: Not using Voice Class Codec
*Sep 5 07:52:36.447: //-1/F6CD57488007/SIP/Media/sipSPICopyPeerDataToCCB: Firewall traversal is not enabled
*Sep 5 07:52:36.447: //-1/F6CD57488007/SIP/Info/sipSPIGetCallConfig: xcoder high-density disabled
*Sep 5 07:52:36.447: //-1/F6CD57488007/SIP/Info/sipSPIGetCallConfig: Flow Mode set to FLOW_THROUGH
*Sep 5 07:52:36.447: //-1/F6CD57488007/SIP/Info/sipSPIContinueNewMsgInvite: Calling name Majdi Sweis, number 2888, Calling oct3 0x00, oct_3a 0x81, ext_priv 0x00, Called number 3349, oct3 0x00
*Sep 5 07:52:36.447: //-1/F6CD57488007/SIP/Info/sipSPIContinueNewMsgInvite: Carrier id code , prev_cid NONE, next_cid NONE, prev_tgrp NONE, next_tgrp NONE
*Sep 5 07:52:36.447: //-1/F6CD57488007/SIP/Info/sipSPIRscmsmAvail: Value returned by check is = 0
*Sep 5 07:52:36.447: //2/F6CD57488007/SIP/Info/sipSPINegotiateSessionExpires: Min-SE Header: 2000
*Sep 5 07:52:36.447: //2/F6CD57488007/SIP/Info/sipSPINegotiateSessionExpires:
Session-Expires value: 2000 refresher: 3
*Sep 5 07:52:36.447: //2/F6CD57488007/SIP/Info/sipSPI_ipip_Add_SessionExpiresParamsToContainer: Session-refresh parameters added to container minse = 2000 session expire = 2000 refresher = 3
*Sep 5 07:52:36.447: //2/F6CD57488007/SIP/Info/sipSPIProcessHistoryInfoHeader: No HI headers recvd from app container
*Sep 5 07:52:36.447: //2/F6CD57488007/SIP/Info/sipSPIProcessDiversionHeader: No diversion headers recvd from app container
*Sep 5 07:52:36.447: //2/F6CD57488007/SIP/Info/sipSPIProcessNotifyCallInfoHeader: Callinfo parsed - Destination url = <sip:10.10.240.1:5060>, duration = 500
*Sep 5 07:52:36.447: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentSDP: No SDP found in inbound container
*Sep 5 07:52:36.447: //2/F6CD57488007/SIP/Info/sipSPIDoQoSNegotiationWithNoMediaLine: Entry
*Sep 5 07:52:36.447: //2/F6CD57488007/SIP/Info/sipSPIDoQoSNegotiationWithNoMediaLine: Local Precondition: 1, Remote Precondition: 1
*Sep 5 07:52:36.447: //2/F6CD57488007/SIP/Info/sipSPICanSetFallbackFlag: Local Fallback is not active
*Sep 5 07:52:36.447: //2/F6CD57488007/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo:
CallID 2, sdp 0x6708B010 channels 0x657979E0
*Sep 5 07:52:36.447: //2/F6CD57488007/SIP/Info/copy_channels:
callId 2 size 0 ptr 0x65A299CC)
*Sep 5 07:52:36.447: //2/F6CD57488007/SIP/Info/sipSPIUpdateSrcSdpFixedPart: Delayed media case...creating new stream
*Sep 5 07:52:36.447: //2/F6CD57488007/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 10.10.30.193
*Sep 5 07:52:36.447: //-1/xxxxxxxxxxxx/SIP/Media/sipSPIReserveRtpPort: reserved port 18648 for stream 1
*Sep 5 07:52:36.447: //2/F6CD57488007/SIP/Info/sipSPIUpdateSrcSdpFixedPart: Reserving rtp port for stream 1, src_port=18648
*Sep 5 07:52:36.451: //2/F6CD57488007/SIP/Media/sipSPIAddSDPMediaPayload: Preferred method of dtmf relay is: 6, with payload: 101
*Sep 5 07:52:36.451: //-1/xxxxxxxxxxxx/SIP/Info/convert_codec_bytes_to_ptime: Values :Codec: g711ulaw codecbytes :160, ptime: 20
*Sep 5 07:52:36.451: //2/F6CD57488007/SIP/Info/sipSPIAddBillingInfoToCcb: sipCallId for billing records = c5be7900-22813e63-74ff7-1f00a0a@10.10.240.1
*Sep 5 07:52:36.451: //2/F6CD57488007/SIP/Info/sipSPI_ipip_store_channel_info: Store channelInfo in CallInfo
*Sep 5 07:52:36.451: //2/F6CD57488007/SIP/Info/sipSPI_ipip_store_channel_info: negotiated dtmf not available, using dialpeer config dtmf = 6
*Sep 5 07:52:36.451: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentQSIG: No QSIG Body found in inbound container
*Sep 5 07:52:36.451: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentQ931: No RawMsg Body found in inbound container
*Sep 5 07:52:36.451: //-1/xxxxxxxxxxxx/SIP/Info/sipSPICreateNewRawMsg: No Data to form The Raw Message
*Sep 5 07:52:36.451: //2/F6CD57488007/SIP/Info/ccsip_set_bearer_capability:
Bearer Capability: Speech (0x00)
*Sep 5 07:52:36.451: //2/F6CD57488007/SIP/Info/sipSPIContinueNewMsgInvite: ccsip_api_call_setup_ind returned: SIP_SUCCESS_DELAYED_MEDIA
*Sep 5 07:52:36.451: //2/F6CD57488007/SIP/Info/sipSPIUaddccCallIdToTable: Adding call id 2 to table
*Sep 5 07:52:36.455: //2/F6CD57488007/SIP/Transport/sipSPITransportSendMessage: msg=0x67073554, addr=10.10.240.1, port=36366, sentBy_port=5060, is_req=0, transport=2, switch=0, callBack=0x00000000
*Sep 5 07:52:36.455: //2/F6CD57488007/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
*Sep 5 07:52:36.455: //2/F6CD57488007/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0
*Sep 5 07:52:36.455: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x67073554, addr=10.10.240.1, port=36366, connId=2 for TCP
*Sep 5 07:52:36.455: //2/F6CD57488007/SIP/State/sipSPIChangeState: 0x6579676C : State change from (STATE_IDLE, SUBSTATE_NONE) to (STATE_RECD_INVITE, SUBSTATE_NONE)
*Sep 5 07:52:36.455: //2/F6CD57488007/SIP/Info/sipSPIProcessContactInfo: Previous Hop 10.10.240.1:5060
*Sep 5 07:52:36.459: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 100 Trying
Via: SIP/2.0/TCP 10.10.240.1:5060;branch=z9hG4bK13e4c84f1f2adf
From: "Majdi Sweis" <sip:2888@10.10.240.1>;tag=ed8670f9-bccc-48ab-a850-c066054d2648-50620776
To: <sip:3349@10.10.30.193>
Date: Thu, 05 Sep 2013 07:52:36 GMT
Call-ID: c5be7900-22813e63-74ff7-1f00a0a@10.10.240.1
CSeq: 101 INVITE
Allow-Events: telephone-event
Server: Cisco-SIPGateway/IOS-12.x
Content-Length: 0
*Sep 5 07:52:36.459: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_PROCEEDING
*Sep 5 07:52:36.463: //2/F6CD57488007/SIP/Info/ccsip_call_statistics: Stats are not supported for IPIP call.
*Sep 5 07:52:36.463: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_DISCONNECT
*Sep 5 07:52:36.463: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 3
*Sep 5 07:52:36.463: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 7
*Sep 5 07:52:36.463: //2/F6CD57488007/SIP/Info/act_recdinvite_disconnect: Performing disconnect
*Sep 5 07:52:36.463: //2/F6CD57488007/SIP/Info/sipSPIUaddCcbToUASRespTable: ****Adding to UAS Response table.
*Sep 5 07:52:36.463: //2/F6CD57488007/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x6579676C key=c5be7900-22813e63-74ff7-1f00a0a@10.10.240.1488070-A6F
*Sep 5 07:52:36.467: //2/F6CD57488007/SIP/Info/sipSPISendInviteResponse: Associated container=0x657D5C04 to Invite Response 404
*Sep 5 07:52:36.467: //2/F6CD57488007/SIP/Transport/sipSPITransportSendMessage: msg=0x670507D0, addr=10.10.240.1, port=36366, sentBy_port=5060, is_req=0, transport=2, switch=0, callBack=0x6131C2BC
*Sep 5 07:52:36.467: //2/F6CD57488007/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
*Sep 5 07:52:36.467: //2/F6CD57488007/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0
*Sep 5 07:52:36.467: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x670507D0, addr=10.10.240.1, port=36366, connId=2 for TCP
*Sep 5 07:52:36.467: //2/F6CD57488007/SIP/Info/sentErrResDisconnecting: Sent an 3456XX Error Response
*Sep 5 07:52:36.467: //2/F6CD57488007/SIP/State/sipSPIChangeState: 0x6579676C : State change from (STATE_RECD_INVITE, SUBSTATE_NONE) to (STATE_DISCONNECTING, SUBSTATE_NONE)
*Sep 5 07:52:36.467: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 404 Not Found
Via: SIP/2.0/TCP 10.10.240.1:5060;branch=z9hG4bK13e4c84f1f2adf
From: "Majdi Sweis" <sip:2888@10.10.240.1>;tag=ed8670f9-bccc-48ab-a850-c066054d2648-50620776
To: <sip:3349@10.10.30.193>;tag=488070-A6F
Date: Thu, 05 Sep 2013 07:52:36 GMT
Call-ID: c5be7900-22813e63-74ff7-1f00a0a@10.10.240.1
CSeq: 101 INVITE
Allow-Events: telephone-event
Server: Cisco-SIPGateway/IOS-12.x
Reason: Q.850;cause=1
Content-Length: 0
*Sep 5 07:52:36.471: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1
*Sep 5 07:52:36.471: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x00000000
*Sep 5 07:52:36.471: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessNewConnMsg: gConnTab=0x66250CC8, addr=10.10.240.1, port=36366, connid=2, transport=TCP
*Sep 5 07:52:36.471: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
ACK sip:3349@10.10.30.193:5060 SIP/2.0
Date: Thu, 05 Sep 2013 08:18:43 GMT
From: "Majdi Sweis" <sip:2888@10.10.240.1>;tag=ed8670f9-bccc-48ab-a850-c066054d2648-50620776
Allow-Events: presence, kpml
Content-Length: 0
To: <sip:3349@10.10.30.193>;tag=488070-A6F
Call-ID: c5be7900-22813e63-74ff7-1f00a0a@10.10.240.1
Via: SIP/2.0/TCP 10.10.240.1:5060;branch=z9hG4bK13e4c84f1f2adf
CSeq: 101 ACK
Max-Forwards: 70
*Sep 5 07:52:36.471: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog
*Sep 5 07:52:36.475: //2/F6CD57488007/SIP/Info/sipSPIFindCcbUASRespTable: *****CCB found in UAS Response table. ccb=0x6579676C
*Sep 5 07:52:36.475: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 10.10.240.1,Port 36366, Transport 2, SentBy Port 5060
*Sep 5 07:52:36.475: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Clock Time Zone is UTC, same as GMT: Using GMT
*Sep 5 07:52:36.475: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 10.10.240.1,Port 36366, Transport 2, SentBy Port 5060
*Sep 5 07:52:36.475: //2/F6CD57488007/SIP/Info/sipSPIIcpifUpdate: CallState: 2 Playout: 0 DiscTime:475148 ConnTime 0
*Sep 5 07:52:36.475: //2/F6CD57488007/SIP/State/sipSPIChangeState: 0x6579676C : State change from (STATE_DISCONNECTING, SUBSTATE_NONE) to (STATE_DEAD, SUBSTATE_NONE)
*Sep 5 07:52:36.475: //2/F6CD57488007/SIP/Call/sipSPICallInfo:
The Call Setup Information is:
Call Control Block (CCB) : 0x6579676C
State of The Call : STATE_DEAD
TCP Sockets Used : YES
Calling Number : 2888
Called Number : 3349
Source IP Address (Sig ): 10.10.30.193
Destn SIP Req Addr
ort : 10.10.240.1:5060Destn SIP Resp Addr
ort : 10.10.240.1:36366Destination Name : 10.10.240.1
*Sep 5 07:52:36.475: //2/F6CD57488007/SIP/Call/sipSPIMediaCallInfo:
Number of Media Streams: 1
Media Stream : 1
Negotiated Codec : No Codec
Negotiated Codec Bytes : 0
Nego. Codec payload : 255 (tx), 255 (rx)
Negotiated Dtmf-relay : 0
Dtmf-relay Payload : 0 (tx), 0 (rx)
Source IP Address (Media): 10.10.30.193
Source IP Port (Media): 18648
Destn IP Address (Media): -
Destn IP Port (Media): 0
Orig Destn IP Address
ort (Media): [ - ]:0*Sep 5 07:52:36.475: //2/F6CD57488007/SIP/Call/sipSPICallInfo:
Disconnect Cause (CC) : 1
Disconnect Cause (SIP) : 404
*Sep 5 07:52:36.475: //2/F6CD57488007/SIP/Info/sipSPIUdeleteccCallIdFromTable: Removing call id 2
*Sep 5 07:52:36.475: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDeleteContextFromTable: Context for key=[2] removed.
*Sep 5 07:52:36.479: //2/F6CD57488007/SIP/Info/sipSPIUdeleteCcbFromUASReqTable: ****Deleting from UAS Request table.
*Sep 5 07:52:36.479: //2/F6CD57488007/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x6579676C key=c5be7900-22813e63-74ff7-1f00a0a@10.10.240.13349
*Sep 5 07:52:36.479: //2/F6CD57488007/SIP/Info/sipSPIUdeleteCcbFromUASRespTable: ****Deleting from UAS Response table.
*Sep 5 07:52:36.479: //2/F6CD57488007/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x6579676C key=c5be7900-22813e63-74ff7-1f00a0a@10.10.240.1488070-A6F
*Sep 5 07:52:36.479: //2/F6CD57488007/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd
*Sep 5 07:52:36.479: //2/F6CD57488007/SIP/Info/ccsip_qos_cleanup: Entry
*Sep 5 07:52:36.479: //2/F6CD57488007/SIP/Info/sipSPI_ipip_free_codec_profile: Codec Profiles Freed
*Sep 5 07:52:36.479: //2/F6CD57488007/SIP/Info/sipSPIUfreeOneCCB: Freeing ccb 6579676C
*Sep 5 07:52:36.479: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContextFromTable: NO context for key[2]
*Sep 5 07:52:56.055: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceHandleConnAgeing: Holder=0x6701BEE4 Connection=0x668C76C4, addr=0.0.0.1, port=168488961, connid=0 has been REFRESHED
*Sep 5 07:52:56.055: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportSetAgeingTimer: Aging timer initiated for holder=0x6701BEE4,addr=10.10.240.1
Router#
Router#
Router#
I am pretty certain that the 404 not found error is the problem, but I am unsure as to whether or not that is the fault of the CCM or the IPO 500. Any help would be greatly appreciated. Thanks!!!