.Aug 28 04:25:31.518: //581/000000000000/SIP/State/sipSPIChangeState: 0x83B5DBE4 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE) .Aug 28 04:25:31.522: //581/000000000000/SIP/Info/ccsip_call_setup_request: This is a TDM-IP call: callID= 581, peer_callID = 580 .Aug 28 04:25:31.522: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_SETUP .Aug 28 04:25:31.522: //581/3CE2441990EC/SIP/Info/sipSPIUaddccCallIdToTable: Adding call id 245 to table .Aug 28 04:25:31.526: //581/3CE2441990EC/SIP/Info/act_idle_continue_call_setup: .Aug 28 04:25:31.526: //581/3CE2441990EC/SIP/Info/sipSPIGetCallConfig: preferred_codec set[0] type :No Codec bytes: 0 .Aug 28 04:25:31.526: //581/3CE2441990EC/SIP/Info/sipSPICanSetFallbackFlag: Local Fallback is not active .Aug 28 04:25:31.526: //581/3CE2441990EC/SIP/Info/sipSPIGetCallConfig: Not using Voice Class Codec .Aug 28 04:25:31.526: //581/3CE2441990EC/SIP/Info/sipSPI_ipip_copy_channelInfo_to_sdp: callid 581, channels 0x0 caps 0x0 .Aug 28 04:25:31.526: //581/3CE2441990EC/SIP/Info/sipSPIValidateGtd: Signal Forward disabled .Aug 28 04:25:31.526: //581/3CE2441990EC/SIP/Info/sipSPIRscmsmAvail: Value returned by check is = 0 .Aug 28 04:25:31.526: //581/3CE2441990EC/SIP/Info/sipSPIUaddCcbToUACTable: ****Adding to UAC table. .Aug 28 04:25:31.530: //581/3CE2441990EC/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x83B5DBE4 key=3CE68AFA-EFFF11E1-90EFE0FD-8B13B9A1@192.168.1.7 .Aug 28 04:25:31.530: //581/3CE2441990EC/SIP/Info/sipSPIUsetBillingProfile: sipCallId for billing records = 3CE68AFA-EFFF11E1-90EFE0FD-8B13B9A1@192.168.1.7 .Aug 28 04:25:31.530: //581/3CE2441990EC/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 192.168.1.7 .Aug 28 04:25:31.530: //-1/xxxxxxxxxxxx/SIP/Media/sipSPIReserveRtpPort: reserved port 18808 for stream 1 .Aug 28 04:25:31.530: //581/3CE2441990EC/SIP/Media/sipSPIAddSDPMediaPayload: Preferred method of dtmf relay is: 6, with payload: 101 .Aug 28 04:25:31.534: //-1/xxxxxxxxxxxx/SIP/Info/convert_codec_bytes_to_ptime: Values :Codec: g711ulaw codecbytes :160, ptime: 20 .Aug 28 04:25:31.534: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 192.168.1.10,Port 5060, Transport 1, SentBy Port 5060 .Aug 28 04:25:31.534: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Converting TimeZone EDT to SIP default timezone = GMT .Aug 28 04:25:31.538: //581/3CE2441990EC/SIP/Event/sipSPICreateRpid: Received Octet3A=0x00 -> Setting ;screen=no ;privacy=off .Aug 28 04:25:31.542: //581/3CE2441990EC/SIP/Transport/sipSPISendInvite: Sending Invite to the transport layer .Aug 28 04:25:31.542: //581/3CE2441990EC/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Global configuration, Switch Transport is FALSE .Aug 28 04:25:31.542: //581/3CE2441990EC/SIP/Transport/sipSPITransportSendMessage: msg=0x83D88470, addr=192.168.1.10, port=5060, sentBy_port=0, is_req=1, transport=1, switch=0, callBack=0x80AAE060 .Aug 28 04:25:31.542: //581/3CE2441990EC/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately .Aug 28 04:25:31.542: //581/3CE2441990EC/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0 .Aug 28 04:25:31.542: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportSetAgeingTimer: Aging timer initiated for holder=0x83D88350,addr=192.168.1.10 .Aug 28 04:25:31.546: //-1/xxxxxxxxxxxx/SIP/Transport/sipCreateConnHolder: Created new holder=0x83D88350, addr=192.168.1.10 .Aug 28 04:25:31.546: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostRequestConnection: Posting UDP conn create request for addr=192.168.1.10, port=5060, context=0x83874CDC .Aug 28 04:25:31.546: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportSetConnWaitTimer: Wait timer set for connection=0x83875F50,addr=192.168.1.10, port=5060 .Aug 28 04:25:31.546: //-1/xxxxxxxxxxxx/SIP/Transport/sipCreateConnInstance: Created new initiated conn=0x83875F50, connid=-1, addr=192.168.1.10, port=5060, transport=udp .Aug 28 04:25:31.546: //-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: Registering ccb=0x83B5DBE4 with connection=0x83875F50 .Aug 28 04:25:31.546: //581/3CE2441990EC/SIP/Transport/sipSPITransportSendMessage: Deferred sending msg=0x83D88470 .Aug 28 04:25:31.550: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWConnectionCreated: context=0x83874CDC .Aug 28 04:25:31.550: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerProcessConnCreated: gConnTab=0x83874CDC, addr=192.168.1.10, port=5060, connid=1, transport=udp .Aug 28 04:25:31.550: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportStopConnWaitTimer: Wait timer stopped for connection=0x83875F50,addr=192.168.1.10, port=5060 .Aug 28 04:25:31.550: //581/3CE2441990EC/SIP/Transport/sipTransportPostInternalMsg: Posting Internal Msg type=0 .Aug 28 04:25:31.550: //581/3CE2441990EC/SIP/Info/ccsip_lock_ccb: CCB locked; reference count=1 .Aug 28 04:25:31.550: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessInternalMsg: context=0x83B5DBE4 .Aug 28 04:25:31.550: //581/3CE2441990EC/SIP/Info/ccsip_unlock_ccb: CCB unlocked; reference count=0 .Aug 28 04:25:31.554: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x83D88470, addr=192.168.1.10, port=5060, connId=1 for UDP .Aug 28 04:25:31.554: //581/3CE2441990EC/SIP/Info/sentInviteRequest: Sent Invite in state STATE_IDLE .Aug 28 04:25:31.554: //-1/xxxxxxxxxxxx/SIP/Info/sentInviteRequest: Transaction active. Facilities will be queued. .Aug 28 04:25:31.554: //581/3CE2441990EC/SIP/State/sipSPIChangeState: 0x83B5DBE4 : State change from (STATE_IDLE, SUBSTATE_NONE) to (STATE_SENT_INVITE, SUBSTATE_NONE) .Aug 28 04:25:31.554: //581/3CE2441990EC/SIP/Media/sipSPIProcessRtpSessions: sipSPIProcessRtpSessions .Aug 28 04:25:31.554: //581/3CE2441990EC/SIP/Media/sipSPIAddStream: Adding stream 1 of type voice+dtmf (callid 581) to the VOIP RTP library .Aug 28 04:25:31.554: //581/3CE2441990EC/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 192.168.1.7 .Aug 28 04:25:31.558: //581/3CE2441990EC/SIP/Media/sipSPIUpdateRtcpSession: sipSPIUpdateRtcpSession for m-line 1 .Aug 28 04:25:31.558: //581/3CE2441990EC/SIP/Media/sipSPIUpdateRtcpSession: rtcp_session info laddr = 192.168.1.7, lport = 18808, raddr = 0.0.0.0, rport=0, do_rtcp=FALSE src_callid = 581, dest_callid = -1, stream type = voice+dtmf, stream direction = RECVONLY media_ip_addr = 0.0.0.0 .Aug 28 04:25:31.558: //581/3CE2441990EC/SIP/Media/sipSPIUpdateRtcpSession: No rtp session, creating a new one .Aug 28 04:25:31.558: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Sent: INVITE sip:2155555757@192.168.1.10:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.7:5060;branch=z9hG4bK2E69EF From: ;tag=388B59F6-1CF6 To: Date: Tue, 28 Aug 2012 04:25:31 GMT Call-ID: 3CE68AFA-EFFF11E1-90EFE0FD-8B13B9A1@192.168.1.7 Supported: 100rel,timer,replaces Min-SE: 1800 Cisco-Guid: 1021461529-4026470881-2431443197-2333325729 User-Agent: Cisco-SIPGateway/IOS-12.x Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO, UPDATE, REGISTER CSeq: 101 INVITE Max-Forwards: 70 Remote-Party-ID: ;party=calling;screen=no;privacy=off Timestamp: 1346127931 Contact: Expires: 180 Allow-Events: telephone-event Content-Type: application/sdp Content-Length: 443 v=0 o=CiscoSystemsSIP-GW-UserAgent 7969 4188 IN IP4 192.168.1.7 s=SIP Call c=IN IP4 192.168.1.7 t=0 0 m=audio 18808 RTP/AVP 0 100 101 c=IN IP4 192.168.1.7 a=rtpmap:0 PCMU/8000 a=rtpmap:100 X-NSE/8000 a=fmtp:100 192-194,200-202 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=X-sqn:0 a=X-cap: 1 audio RTP/AVP 100 a=X-cpar: a=rtpmap:100 X-NSE/8000 a=X-cpar: a=fmtp:100 192-194,200-202 a=X-cap: 2 image udptl t38 .Aug 28 04:25:31.570: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpSocketReads: Msg enqueued for SPI with IP addr: 192.168.1.10:5060 .Aug 28 04:25:31.570: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x00000000 .Aug 28 04:25:31.570: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.7:5060;branch=z9hG4bK2E69EF;received=192.168.1.7 From: ;tag=388B59F6-1CF6 To: Call-ID: 3CE68AFA-EFFF11E1-90EFE0FD-8B13B9A1@192.168.1.7 CSeq: 101 INVITE Server: Asterisk PBX 1.8.15.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces Contact: Content-Length: 0 .Aug 28 04:25:31.574: //581/3CE2441990EC/SIP/State/sipSPIChangeState: 0x83B5DBE4 : State change from (STATE_SENT_INVITE, SUBSTATE_NONE) to (STATE_RECD_PROCEEDING, SUBSTATE_PROCEEDING_PROCEEDING) .Aug 28 04:25:31.586: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpSocketReads: Msg enqueued for SPI with IP addr: 192.168.1.10:5060 .Aug 28 04:25:31.586: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x00000000 .Aug 28 04:25:31.590: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.7:5060;branch=z9hG4bK2E69EF;received=192.168.1.7 From: ;tag=388B59F6-1CF6 To: ;tag=as559decfa Call-ID: 3CE68AFA-EFFF11E1-90EFE0FD-8B13B9A1@192.168.1.7 CSeq: 101 INVITE Server: Asterisk PBX 1.8.15.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces Contact: Content-Type: application/sdp Content-Length: 235 v=0 o=root 989907170 989907170 IN IP4 192.168.1.10 s=Asterisk PBX 1.8.15.0 c=IN IP4 192.168.1.10 t=0 0 m=audio 28148 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv .Aug 28 04:25:31.594: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetGtdBody: No valid GTD body found. .Aug 28 04:25:31.594: //581/3CE2441990EC/SIP/Info/sipSPIhandle200OKInvite: Transaction active. Facilities will be queued. .Aug 28 04:25:31.594: //581/3CE2441990EC/SIP/Info/sipSPIhandle200OKInvite: *** This ccb is the parent .Aug 28 04:25:31.594: //581/3CE2441990EC/SIP/Info/sipSPICompareRespMediaInfo: No Comparsion needed as 18x response SDP is either absent or ignored .Aug 28 04:25:31.594: //581/3CE2441990EC/SIP/Info/sipSPIDoMediaNegotiation: Number of m-lines = 1 .Aug 28 04:25:31.598: //581/3CE2441990EC/SIP/Info/sipSPIDoAudioNegotiation: Codec (g711ulaw) Negotiation Successful on Static Payload for m-line 1 .Aug 28 04:25:31.598: //-1/xxxxxxxxxxxx/SIP/Info/convert_ptime_to_codec_bytes: Values :Codec: g711ulaw ptime :20, codecbytes: 160 .Aug 28 04:25:31.598: //-1/xxxxxxxxxxxx/SIP/Info/convert_codec_bytes_to_ptime: Values :Codec: g711ulaw codecbytes :160, ptime: 20 .Aug 28 04:25:31.598: //581/3CE2441990EC/SIP/Media/sipSPIDoPtimeNegotiation: Offered ptime:20, Negotiated ptime:20 Negotiated codec bytes: 160 for codec g711ulaw .Aug 28 04:25:31.598: //581/3CE2441990EC/SIP/Info/sipSPIDoDTMFRelayNegotiation: m-line index 1 .Aug 28 04:25:31.598: //581/3CE2441990EC/SIP/Info/sipSPICheckDynPayloadUse: Dynamic payload(101) could not be reserved. .Aug 28 04:25:31.598: //581/3CE2441990EC/SIP/Info/sipSPIDoDTMFRelayNegotiation: Payload type (101) is reserved for requested dtmf relay mode. .Aug 28 04:25:31.598: //581/3CE2441990EC/SIP/Info/sipSPIDoDTMFRelayNegotiation: Case of full named event(NE) match in fmtp list of events. .Aug 28 04:25:31.602: //-1/xxxxxxxxxxxx/SIP/Info/sip_sdp_get_modem_relay_cap_params: NSE payload from X-cap = 0 .Aug 28 04:25:31.602: //581/3CE2441990EC/SIP/Info/sip_select_modem_relay_params: X-tmr not present in SDP. Disable modem relay .Aug 28 04:25:31.602: //581/3CE2441990EC/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 28 04:25:31.602: //581/3CE2441990EC/SIP/Info/sipSPIDoAudioNegotiation: Codec negotiation successful for media line 1 payload_type=0, codec_bytes=160, codec=g711ulaw, dtmf_relay=rtp-nte stream_type=voice+dtmf (1), dest_ip_address=192.168.1.10, dest_port=28148 .Aug 28 04:25:31.602: //581/3CE2441990EC/SIP/Media/sipSPIUpdCallWithSdpInfo: Preferred Codec : g711ulaw, bytes :160 Preferred DTMF relay : rtp-nte Preferred NTE payload : 101 Early Media : No Delayed Media : No Bridge Done : No New Media : No DSP DNLD Reqd : No .Aug 28 04:25:31.606: //581/3CE2441990EC/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 192.168.1.7 .Aug 28 04:25:31.606: //581/3CE2441990EC/SIP/Media/sipSPIUpdCallWithSdpInfo: Stream type : voice+dtmf Media line : 1 State : STREAM_ADDING (2) Callid : 581 Negotiated Codec : g711ulaw, bytes :160 Negotiated DTMF relay : rtp-nte Negotiated NTE payload : 101 Negotiated CN payload : 0 Media Srce Addr/Port : 192.168.1.7:18808 Media Dest Addr/Port : 192.168.1.10:28148 .Aug 28 04:25:31.606: //581/3CE2441990EC/SIP/Info/sipSPIProcessMediaChanges: sipSPIProcessMediaChanges .Aug 28 04:25:31.606: //581/3CE2441990EC/SIP/Info/sipSPIhandle200OKInvite: ccsip_api_call_connect_media returned: SIP_SUCCESS .Aug 28 04:25:31.606: //581/3CE2441990EC/SIP/State/sipSPIChangeState: 0x83B5DBE4 : State change from (STATE_RECD_PROCEEDING, SUBSTATE_PROCEEDING_PROCEEDING) to (STATE_RECD_PROCEEDING, SUBSTATE_NONE) .Aug 28 04:25:31.606: //-1/xxxxxxxxxxxx/SIP/Info/sipSPICreateRawMsg: No GTD passed. .Aug 28 04:25:31.606: //581/3CE2441990EC/SIP/Info/sipSPIhandle200OKInvite: ccsip_api_call_connected returned: SIP_SUCCESS .Aug 28 04:25:31.610: //581/3CE2441990EC/SIP/Transport/sipSPISendAck: Sending ACK to the transport layer .Aug 28 04:25:31.610: //581/3CE2441990EC/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Global configuration, Switch Transport is FALSE .Aug 28 04:25:31.610: //581/3CE2441990EC/SIP/Transport/sipSPITransportSendMessage: msg=0x83D88590, addr=192.168.1.10, port=5060, sentBy_port=0, is_req=1, transport=1, switch=0, callBack=0x80AAF6C8 .Aug 28 04:25:31.614: //581/3CE2441990EC/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately .Aug 28 04:25:31.614: //581/3CE2441990EC/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0 .Aug 28 04:25:31.614: //581/3CE2441990EC/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x83D88590 .Aug 28 04:25:31.614: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x83D88590, addr=192.168.1.10, port=5060, connId=1 for UDP .Aug 28 04:25:31.614: //581/3CE2441990EC/SIP/State/sipSPIChangeState: 0x83B5DBE4 : State change from (STATE_RECD_PROCEEDING, SUBSTATE_NONE) to (STATE_ACTIVE, SUBSTATE_NONE) .Aug 28 04:25:31.614: //581/3CE2441990EC/SIP/Call/sipSPICallInfo: The Call Setup Information is: Call Control Block (CCB) : 0x83B5DBE4 State of The Call : STATE_ACTIVE TCP Sockets Used : NO Calling Number : 9910 Called Number : 2155555757 Source IP Address (Sig ): 192.168.1.7 Destn SIP Req Addr:Port : 192.168.1.10:5060 Destn SIP Resp Addr:Port : 192.168.1.10:5060 Destination Name : 192.168.1.10 .Aug 28 04:25:31.614: //581/3CE2441990EC/SIP/Call/sipSPIMediaCallInfo: Number of Media Streams: 1 Media Stream : 1 Negotiated Codec : g711ulaw Negotiated Codec Bytes : 160 Negotiated Dtmf-relay : 6 Dtmf-relay Payload : 101 Source IP Address (Media): 192.168.1.7 Source IP Port (Media): 18808 Destn IP Address (Media): 192.168.1.10 Destn IP Port (Media): 28148 Orig Destn IP Address:Port (Media): 0.0.0.0:0 .Aug 28 04:25:31.618: //581/3CE2441990EC/SIP/Info/sipSPICallActive: Transaction Complete. Lock on Facilities released. .Aug 28 04:25:31.618: //581/3CE2441990EC/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd .Aug 28 04:25:31.622: //581/3CE2441990EC/SIP/Info/ccsip_bridge: confID = 290, srcCallID = 581, dstCallID = 580 .Aug 28 04:25:31.622: //581/3CE2441990EC/SIP/Info/sipSPIUupdateCcCallIds: Old src/dest ccCallids: -1/-1, new src/dest ccCallids: 581/580 .Aug 28 04:25:31.622: //581/3CE2441990EC/SIP/Info/sipSPIUupdateCcCallIds: Old streamcallid=581, new streamcallid=581 .Aug 28 04:25:31.622: //581/3CE2441990EC/SIP/Media/sipSPIProcessRtpSessions: sipSPIProcessRtpSessions .Aug 28 04:25:31.622: //581/3CE2441990EC/SIP/Media/sipSPIAddStream: Adding stream 1 of type voice+dtmf (callid 581) to the VOIP RTP library .Aug 28 04:25:31.622: //581/3CE2441990EC/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 192.168.1.7 .Aug 28 04:25:31.622: //581/3CE2441990EC/SIP/Media/sipSPIUpdateRtcpSession: sipSPIUpdateRtcpSession for m-line 1 .Aug 28 04:25:31.622: //581/3CE2441990EC/SIP/Media/sipSPIUpdateRtcpSession: rtcp_session info laddr = 192.168.1.7, lport = 18808, raddr = 192.168.1.10, rport=28148, do_rtcp=TRUE src_callid = 581, dest_callid = 580, stream type = voice+dtmf, stream direction = SENDRECV media_ip_addr = 192.168.1.10 .Aug 28 04:25:31.622: //581/3CE2441990EC/SIP/Media/sipSPIUpdateRtcpSession: RTP session already created - update .Aug 28 04:25:31.626: //581/3CE2441990EC/SIP/Info/sipSPICreateAndStartRtpTimer: .Aug 28 04:25:31.626: //581/3CE2441990EC/SIP/Info/sipSPICreateAndStartRtpTimer: Valid RTP/RTCP session found and CLI enabled to create and start the inactivity timer. .Aug 28 04:25:31.626: //581/3CE2441990EC/SIP/Info/sipSPICreateAndStartRtpTimer: Media Inactivity timer created for stream 1. Mfactor(from CLI): 5 RTCP bandwidth: 500 RTCP Interval(in ms): 5000 Normalized RTCP interval (in ms):25000 .Aug 28 04:25:31.626: //581/3CE2441990EC/SIP/Media/sipSPIGetNewLocalMediaDirection: New Remote Media Direction = SENDRECV Present Local Media Direction = SENDRECV New Local Media Direction = SENDRECV retVal = 0 .Aug 28 04:25:31.630: //581/3CE2441990EC/SIP/Info/ccsip_get_rtcp_session_parameters: CURRENT VALUES: stream_callid=581, current_seq_num=0x1E5 .Aug 28 04:25:31.630: //581/3CE2441990EC/SIP/Info/ccsip_get_rtcp_session_parameters: NEW VALUES: stream_callid=581, current_seq_num=0x12DA .Aug 28 04:25:31.630: //581/3CE2441990EC/SIP/Info/ccsip_caps_ind: Load DSP with negotiated codec: g711ulaw, Bytes=160 .Aug 28 04:25:31.630: //581/3CE2441990EC/SIP/Info/ccsip_caps_ind: Set forking flag to 0x0 .Aug 28 04:25:31.630: //581/3CE2441990EC/SIP/Info/sipSPISetDTMFRelayMode: Set DSP for dtmf-relay = CC_CAP_DTMF_RELAY_NTE_AND_OOB .Aug 28 04:25:31.630: //581/3CE2441990EC/SIP/Info/sip_set_modem_caps: Preferred (or the one that came from DSM) modem relay=0, from CLI config=0 .Aug 28 04:25:31.630: //581/3CE2441990EC/SIP/Info/sip_set_modem_caps: Disabling Modem Relay... .Aug 28 04:25:31.630: //581/3CE2441990EC/SIP/Info/sip_set_modem_caps: Negotiation already Done. Set negotiated Modem caps and generate SDP Xcap list .Aug 28 04:25:31.630: //581/3CE2441990EC/SIP/Info/sip_set_modem_caps: Modem Relay & Passthru both disabled .Aug 28 04:25:31.634: //581/3CE2441990EC/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 28 04:25:31.634: //581/3CE2441990EC/SIP/Media/sipSPISetStreamInfo: 1 Active Streams .Aug 28 04:25:31.634: //581/3CE2441990EC/SIP/Media/sipSPISetStreamInfo: Adding stream type (voice+dtmf) from media line 1 .Aug 28 04:25:31.634: //581/3CE2441990EC/SIP/Media/sipSPISetStreamInfo: caps.stream_count=1,caps.stream[0].stream_type=0x2, caps.stream_list.xmitFunc= .Aug 28 04:25:31.634: //581/3CE2441990EC/SIP/Media/sipSPISetStreamInfo: voip_rtp_xmit, caps.stream_list.context= .Aug 28 04:25:31.634: //581/3CE2441990EC/SIP/Media/sipSPISetStreamInfo: 0x83DD5ED0 (gccb) .Aug 28 04:25:31.634: //581/3CE2441990EC/SIP/Info/ccsip_caps_ind: Load DSP with codec : g711ulaw, Bytes=160 .Aug 28 04:25:31.634: //581/3CE2441990EC/SIP/Info/ccsip_caps_ind: ccsip_caps_ind: ccb->flags_ipip = 0x20F .Aug 28 04:25:31.638: //581/3CE2441990EC/SIP/Info/ccsip_caps_ack: Set forking flag to 0x0 .Aug 28 04:25:31.750: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Sent: ACK sip:2155555757@192.168.1.10:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.7:5060;branch=z9hG4bK2E71D91 From: ;tag=388B59F6-1CF6 To: ;tag=as559decfa Date: Tue, 28 Aug 2012 04:25:31 GMT Call-ID: 3CE68AFA-EFFF11E1-90EFE0FD-8B13B9A1@192.168.1.7 Max-Forwards: 70 CSeq: 101 ACK Content-Length: 0 .Aug 28 04:25:31.754: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpSocketReads: Msg enqueued for SPI with IP addr: 192.168.1.10:5060 .Aug 28 04:25:31.758: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x00000000 .Aug 28 04:25:31.758: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.7:5060;branch=z9hG4bK2E69EF;received=192.168.1.7 From: ;tag=388B59F6-1CF6 To: ;tag=as559decfa Call-ID: 3CE68AFA-EFFF11E1-90EFE0FD-8B13B9A1@192.168.1.7 CSeq: 101 INVITE Server: Asterisk PBX 1.8.15.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces Contact: Content-Type: application/sdp Content-Length: 235 v=0 o=root 989907170 989907170 IN IP4 192.168.1.10 s=Asterisk PBX 1.8.15.0 c=IN IP4 192.168.1.10 t=0 0 m=audio 28148 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv .Aug 28 04:25:31.762: //581/3CE2441990EC/SIP/Transport/sipSPISendAck: Sending ACK to the transport layer .Aug 28 04:25:31.762: //581/3CE2441990EC/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Global configuration, Switch Transport is FALSE .Aug 28 04:25:31.762: //581/3CE2441990EC/SIP/Transport/sipSPITransportSendMessage: msg=0x83D88590, addr=192.168.1.10, port=5060, sentBy_port=0, is_req=1, transport=1, switch=0, callBack=0x00000000 .Aug 28 04:25:31.762: //581/3CE2441990EC/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately .Aug 28 04:25:31.762: //581/3CE2441990EC/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0 .Aug 28 04:25:31.766: //581/3CE2441990EC/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x83D88590 .Aug 28 04:25:31.766: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x83D88590, addr=192.168.1.10, port=5060, connId=1 for UDP .Aug 28 04:25:31.766: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Sent: ACK sip:2155555757@192.168.1.10:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.7:5060;branch=z9hG4bK2E71D91 From: ;tag=388B59F6-1CF6 To: ;tag=as559decfa Date: Tue, 28 Aug 2012 04:25:31 GMT Call-ID: 3CE68AFA-EFFF11E1-90EFE0FD-8B13B9A1@192.168.1.7 Max-Forwards: 70 CSeq: 101 ACK Content-Length: 0 vgw1# vgw1# vgw1# vgw1# vgw1# .Aug 28 04:25:52.161: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpSocketReads: Msg enqueued for SPI with IP addr: 192.168.1.10:5060 .Aug 28 04:25:52.165: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x00000000 .Aug 28 04:25:52.165: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: INVITE sip:9910@192.168.1.7:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.10:5060;branch=z9hG4bK71012021 Max-Forwards: 70 From: ;tag=as559decfa To: ;tag=388B59F6-1CF6 Contact: Call-ID: 3CE68AFA-EFFF11E1-90EFE0FD-8B13B9A1@192.168.1.7 CSeq: 102 INVITE User-Agent: Asterisk PBX 1.8.15.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces Remote-Party-ID: "Sales Desk 2" ;party=called;privacy=off;screen=no Content-Type: application/sdp Content-Length: 235 v=0 o=root 989907170 989907171 IN IP4 192.168.1.10 s=Asterisk PBX 1.8.15.0 c=IN IP4 192.168.1.10 t=0 0 m=audio 28148 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv .Aug 28 04:25:52.169: //581/3CE2441990EC/SIP/Info/sipSPICheckFromToRequest: Found matching CB 83B5DBE4 .Aug 28 04:25:52.169: //581/3CE2441990EC/SIP/Info/ccsip_new_msg_preprocessor: ****Found CCB in UAC table .Aug 28 04:25:52.169: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 192.168.1.10,Port 5060, Transport 1, SentBy Port 5060 .Aug 28 04:25:52.169: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Converting TimeZone EDT to SIP default timezone = GMT .Aug 28 04:25:52.173: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 192.168.1.10,Port 5060, Transport 1, SentBy Port 5060 .Aug 28 04:25:52.173: //581/3CE2441990EC/SIP/Info/sact_active_new_message_request: Case of Mid-Call INVITE/UPDATE in ACTIVE STATE .Aug 28 04:25:52.173: //581/3CE2441990EC/SIP/Info/sipSPISetInfoFromRpid: Received current remote name: Sales Desk 2, current remote number: 112 .Aug 28 04:25:52.173: //581/3CE2441990EC/SIP/Info/sipSPISetInfoFromRpid: Received ;screen=no ;privacy=off -> Setting Octet3A 0x80, extended_privacy 0x00 .Aug 28 04:25:52.177: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetGtdBody: No valid GTD body found. .Aug 28 04:25:52.177: //581/3CE2441990EC/SIP/Info/sipSPIDoMediaNegotiation: Number of m-lines = 1 .Aug 28 04:25:52.177: //581/3CE2441990EC/SIP/Info/sipSPIDoAudioNegotiation: Codec (g711ulaw) Negotiation Successful on Static Payload for m-line 1 .Aug 28 04:25:52.181: //-1/xxxxxxxxxxxx/SIP/Info/convert_ptime_to_codec_bytes: Values :Codec: g711ulaw ptime :20, codecbytes: 160 .Aug 28 04:25:52.181: //-1/xxxxxxxxxxxx/SIP/Info/convert_codec_bytes_to_ptime: Values :Codec: g711ulaw codecbytes :160, ptime: 20 .Aug 28 04:25:52.181: //581/3CE2441990EC/SIP/Media/sipSPIDoPtimeNegotiation: Offered ptime:20, Negotiated ptime:20 Negotiated codec bytes: 160 for codec g711ulaw .Aug 28 04:25:52.181: //581/3CE2441990EC/SIP/Info/sipSPIDoDTMFRelayNegotiation: m-line index 1 .Aug 28 04:25:52.181: //581/3CE2441990EC/SIP/Info/sipSPIDoDTMFRelayNegotiation: Case of full named event(NE) match in fmtp list of events. .Aug 28 04:25:52.181: //-1/xxxxxxxxxxxx/SIP/Info/sip_sdp_get_modem_relay_cap_params: NSE payload from X-cap = 0 .Aug 28 04:25:52.181: //581/3CE2441990EC/SIP/Info/sip_do_nse_negotiation: Remote NSE payload = local one = 0, Use it .Aug 28 04:25:52.181: //581/3CE2441990EC/SIP/Info/sip_select_modem_relay_params: X-tmr not present in SDP. Disable modem relay .Aug 28 04:25:52.181: //581/3CE2441990EC/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 28 04:25:52.185: //581/3CE2441990EC/SIP/Info/sipSPIDoAudioNegotiation: Codec negotiation successful for media line 1 payload_type=0, codec_bytes=160, codec=g711ulaw, dtmf_relay=rtp-nte stream_type=voice+dtmf (1), dest_ip_address=192.168.1.10, dest_port=28148 .Aug 28 04:25:52.185: //581/3CE2441990EC/SIP/Media/sipSPICompareStreams: stream 1 dest_port: old=28148 new=28148 .Aug 28 04:25:52.185: //581/3CE2441990EC/SIP/Media/sipSPIGetNewLocalMediaDirection: New Remote Media Direction = SENDRECV Present Local Media Direction = SENDRECV New Local Media Direction = SENDRECV retVal = 0 .Aug 28 04:25:52.185: //581/3CE2441990EC/SIP/Media/sipSPICompareStreams: Flags set for stream 1: RTP_CHANGE=No CAPS_CHANGE=No .Aug 28 04:25:52.185: //581/3CE2441990EC/SIP/Media/sipSPICompareSDP: Flags set for call: NEW_MEDIA=No DSPDNLD_REQD=No IPIP_MEDIA=No .Aug 28 04:25:52.185: //581/3CE2441990EC/SIP/Media/sipSPIUpdCallWithSdpInfo: Preferred Codec : g711ulaw, bytes :160 Preferred DTMF relay : rtp-nte Preferred NTE payload : 101 Early Media : No Delayed Media : No Bridge Done : Yes New Media : No DSP DNLD Reqd : No .Aug 28 04:25:52.185: //581/3CE2441990EC/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 192.168.1.7 .Aug 28 04:25:52.189: //581/3CE2441990EC/SIP/Media/sipSPIUpdCallWithSdpInfo: Stream type : voice+dtmf Media line : 1 State : STREAM_ACTIVE (5) Callid : 581 Negotiated Codec : g711ulaw, bytes :160 Negotiated DTMF relay : rtp-nte Negotiated NTE payload : 101 Negotiated CN payload : 0 Media Srce Addr/Port : 192.168.1.7:18808 Media Dest Addr/Port : 192.168.1.10:28148 .Aug 28 04:25:52.189: //581/3CE2441990EC/SIP/Info/sipSPIProcessMediaChanges: sipSPIProcessMediaChanges .Aug 28 04:25:52.189: //581/3CE2441990EC/SIP/Info/sipSPIIncomingCallSDP: SDP already there use old SDP and update media if needed .Aug 28 04:25:52.189: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetMediaDirectionForStream: Setting Media direction SENDRECV for stream 1 .Aug 28 04:25:52.189: //581/3CE2441990EC/SIP/Info/sipSPIUpdateSrcSdpVariablePart: Setting stream 1 portnum to 18808 .Aug 28 04:25:52.189: //581/3CE2441990EC/SIP/Info/sipSPIUpdateSrcSdpVariablePart: Negotiated method of dtmf relayand pyld: 6 101 .Aug 28 04:25:52.193: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_MEDIA_EVENT .Aug 28 04:25:52.193: //581/3CE2441990EC/SIP/State/sipSPIChangeState: 0x83B5DBE4 : State change from (STATE_ACTIVE, SUBSTATE_NONE) to (STATE_MIDCALL_LOCAL_RESP_PENDING, SUBSTATE_NONE) .Aug 28 04:25:52.193: //581/3CE2441990EC/SIP/Info/sipSPIHandleIncomingMidCallInvite: ccsip_api_request_offer returned: SIP_SUCCESS .Aug 28 04:25:52.197: //581/3CE2441990EC/SIP/Event/sipSPICreateRpid: Received Octet3A=0x00 -> Setting ;screen=no ;privacy=off .Aug 28 04:25:52.197: //581/3CE2441990EC/SIP/Transport/sipSPITransportSendMessage: msg=0x83D88470, addr=192.168.1.10, port=5060, sentBy_port=5060, is_req=0, transport=1, switch=0, callBack=0x00000000 .Aug 28 04:25:52.197: //581/3CE2441990EC/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately .Aug 28 04:25:52.197: //581/3CE2441990EC/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0 .Aug 28 04:25:52.197: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x83D88470, addr=192.168.1.10, port=5060, connId=0 for UDP .Aug 28 04:25:52.197: //581/3CE2441990EC/SIP/Info/sipSPIProcessContactInfo: Previous Hop 192.168.1.10:5060 .Aug 28 04:25:52.197: //581/3CE2441990EC/SIP/Info/act_handle_app_media_event: Received media sip event SIP_RESPONSE_ANSWER .Aug 28 04:25:52.201: //581/3CE2441990EC/SIP/Event/sipSPICreateRpid: Received Octet3A=0x00 -> Setting ;screen=no ;privacy=off .Aug 28 04:25:52.205: //581/3CE2441990EC/SIP/Transport/sipSPISendInviteResponse: Sending 200OK Response to the Transport Layer .Aug 28 04:25:52.205: //581/3CE2441990EC/SIP/Transport/sipSPITransportSendMessage: msg=0x83D882C0, addr=192.168.1.10, port=5060, sentBy_port=5060, is_req=0, transport=1, switch=0, callBack=0x80AAF2E0 .Aug 28 04:25:52.205: //581/3CE2441990EC/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately .Aug 28 04:25:52.205: //581/3CE2441990EC/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0 .Aug 28 04:25:52.205: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x83D882C0, addr=192.168.1.10, port=5060, connId=0 for UDP .Aug 28 04:25:52.205: //581/3CE2441990EC/SIP/Info/sentResponseStartConnectTimer: Sent Response, start ConnectTimer .Aug 28 04:25:52.209: //581/3CE2441990EC/SIP/Info/sipSPIProcessHoldTimerForCall: Media IP Addr 192.168.1.10, RTCP Type 3 .Aug 28 04:25:52.209: //581/3CE2441990EC/SIP/Info/sipSPIStopHoldTimer: Stopping hold timer .Aug 28 04:25:52.209: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Sent: SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.10:5060;branch=z9hG4bK71012021 From: ;tag=as559decfa To: ;tag=388B59F6-1CF6 Date: Tue, 28 Aug 2012 04:25:52 GMT Call-ID: 3CE68AFA-EFFF11E1-90EFE0FD-8B13B9A1@192.168.1.7 Server: Cisco-SIPGateway/IOS-12.x CSeq: 102 INVITE Allow-Events: telephone-event Remote-Party-ID: ;party=called;screen=no;privacy=off Content-Length: 0 .Aug 28 04:25:52.213: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Sent: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.10:5060;branch=z9hG4bK71012021 From: ;tag=as559decfa To: ;tag=388B59F6-1CF6 Date: Tue, 28 Aug 2012 04:25:52 GMT Call-ID: 3CE68AFA-EFFF11E1-90EFE0FD-8B13B9A1@192.168.1.7 Server: Cisco-SIPGateway/IOS-12.x CSeq: 102 INVITE Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO, UPDATE, REGISTER Supported: replaces Allow-Events: telephone-event Remote-Party-ID: ;party=called;screen=no;privacy=off Contact: Content-Type: application/sdp Content-Length: 244 v=0 o=CiscoSystemsSIP-GW-UserAgent 7969 4188 IN IP4 192.168.1.7 s=SIP Call c=IN IP4 192.168.1.7 t=0 0 m=audio 18808 RTP/AVP 0 101 c=IN IP4 192.168.1.7 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 .Aug 28 04:25:52.217: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpSocketReads: Msg enqueued for SPI with IP addr: 192.168.1.10:5060 .Aug 28 04:25:52.217: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x00000000 .Aug 28 04:25:52.221: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: UPDATE sip:9910@192.168.1.7:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.10:5060;branch=z9hG4bK457541d5 Max-Forwards: 70 From: ;tag=as559decfa To: ;tag=388B59F6-1CF6 Contact: Call-ID: 3CE68AFA-EFFF11E1-90EFE0FD-8B13B9A1@192.168.1.7 CSeq: 103 UPDATE User-Agent: Asterisk PBX 1.8.15.0 Remote-Party-ID: "testing" ;party=calling;privacy=off;screen=no X-Asterisk-rpid-update: Yes Content-Length: 0 .Aug 28 04:25:52.221: //581/3CE2441990EC/SIP/Info/sipSPICheckFromToRequest: Found matching CB 83B5DBE4 .Aug 28 04:25:52.221: //581/3CE2441990EC/SIP/Info/ccsip_new_msg_preprocessor: ****Found CCB in UAC table .Aug 28 04:25:52.221: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 192.168.1.10,Port 5060, Transport 1, SentBy Port 5060 .Aug 28 04:25:52.225: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Converting TimeZone EDT to SIP default timezone = GMT .Aug 28 04:25:52.225: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 192.168.1.10,Port 5060, Transport 1, SentBy Port 5060 .Aug 28 04:25:52.225: //581/3CE2441990EC/SIP/Error/sact_local_resp_pending_new_message_request: Ignoring request(UPDATE) .Aug 28 04:25:52.229: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpSocketReads: Msg enqueued for SPI with IP addr: 192.168.1.10:5060 .Aug 28 04:25:52.233: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x00000000 .Aug 28 04:25:52.233: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: ACK sip:9910@192.168.1.7:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.10:5060;branch=z9hG4bK049305d9 Max-Forwards: 70 From: ;tag=as559decfa To: ;tag=388B59F6-1CF6 Contact: Call-ID: 3CE68AFA-EFFF11E1-90EFE0FD-8B13B9A1@192.168.1.7 CSeq: 102 ACK User-Agent: Asterisk PBX 1.8.15.0 Content-Length: 0 .Aug 28 04:25:52.233: //581/3CE2441990EC/SIP/Info/sipSPICheckFromToRequest: Found matching CB 83B5DBE4 .Aug 28 04:25:52.237: //581/3CE2441990EC/SIP/Info/ccsip_new_msg_preprocessor: ****Found CCB in UAC table .Aug 28 04:25:52.237: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 192.168.1.10,Port 5060, Transport 1, SentBy Port 5060 .Aug 28 04:25:52.237: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Converting TimeZone EDT to SIP default timezone = GMT .Aug 28 04:25:52.237: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 192.168.1.10,Port 5060, Transport 1, SentBy Port 5060 .Aug 28 04:25:52.237: //581/3CE2441990EC/SIP/Info/sipSPIProcessIncomingAckForMidCall: Processing MidCall ACK .Aug 28 04:25:52.237: //581/3CE2441990EC/SIP/State/sipSPIChangeState: 0x83B5DBE4 : State change from (STATE_MIDCALL_LOCAL_RESP_PENDING, SUBSTATE_NONE) to (STATE_ACTIVE, SUBSTATE_NONE) .Aug 28 04:25:52.273: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpSocketReads: Msg enqueued for SPI with IP addr: 192.168.1.10:5060 .Aug 28 04:25:52.273: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x00000000 .Aug 28 04:25:52.273: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: UPDATE sip:9910@192.168.1.7:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.10:5060;branch=z9hG4bK457541d5 Max-Forwards: 70 From: ;tag=as559decfa To: ;tag=388B59F6-1CF6 Contact: Call-ID: 3CE68AFA-EFFF11E1-90EFE0FD-8B13B9A1@192.168.1.7 CSeq: 103 UPDATE User-Agent: Asterisk PBX 1.8.15.0 Remote-Party-ID: "testing" ;party=calling;privacy=off;screen=no X-Asterisk-rpid-update: Yes Content-Length: 0 .Aug 28 04:25:52.277: //581/3CE2441990EC/SIP/Info/sipSPICheckFromToRequest: Found matching CB 83B5DBE4 .Aug 28 04:25:52.277: //581/3CE2441990EC/SIP/Info/ccsip_new_msg_preprocessor: ****Found CCB in UAC table .Aug 28 04:25:52.277: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 192.168.1.10,Port 5060, Transport 1, SentBy Port 5060 .Aug 28 04:25:52.277: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Converting TimeZone EDT to SIP default timezone = GMT .Aug 28 04:25:52.281: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 192.168.1.10,Port 5060, Transport 1, SentBy Port 5060 .Aug 28 04:25:52.281: //581/3CE2441990EC/SIP/Error/sip_process_request_cseq: Last method and CSEQ:110 103 .Aug 28 04:25:52.281: //581/3CE2441990EC/SIP/Error/sip_process_request_cseq: INVITE CSEQ: 102 .Aug 28 04:25:52.281: //581/3CE2441990EC/SIP/Error/sip_process_request_cseq: Recvd method and CSEQ: 112 103 .Aug 28 04:25:52.281: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_set_release_source_for_peer: ownCallId[581], src[6] .Aug 28 04:25:52.285: //581/3CE2441990EC/SIP/Info/ccsip_set_cc_cause_for_spi_err: Categorized cause:100, category:100 .Aug 28 04:25:52.285: //581/3CE2441990EC/SIP/Transport/sipSPISendErrorResponse: Sending ERROR Response to the transport layer .Aug 28 04:25:52.285: //581/3CE2441990EC/SIP/Transport/sipSPITransportSendMessage: msg=0x83D882C0, addr=192.168.1.10, port=5060, sentBy_port=5060, is_req=0, transport=1, switch=0, callBack=0x00000000 .Aug 28 04:25:52.285: //581/3CE2441990EC/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately .Aug 28 04:25:52.285: //581/3CE2441990EC/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0 .Aug 28 04:25:52.285: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x83D882C0, addr=192.168.1.10, port=5060, connId=0 for UDP .Aug 28 04:25:52.289: //-1/xxxxxxxxxxxx/SIP/Error/sipSPICheckRequest: CheckRequest fail on method 112 error code: 2 and status: 500 .Aug 28 04:25:52.289: //-1/xxxxxxxxxxxx/SIP/Error/sact_active_new_message_request: Check request failed .Aug 28 04:25:52.289: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Sent: SIP/2.0 500 Internal Server Error Via: SIP/2.0/UDP 192.168.1.10:5060;branch=z9hG4bK457541d5 From: ;tag=as559decfa To: ;tag=388B59F6-1CF6 Call-ID: 3CE68AFA-EFFF11E1-90EFE0FD-8B13B9A1@192.168.1.7 CSeq: 103 UPDATE Content-Length: 0 vgw1# vgw1# vgw1# vgw1# vgw1# vgw1# vgw1# vgw1# vgw1# vgw1# .Aug 28 04:25:58.740: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_DISCONNECT .Aug 28 04:25:58.740: //581/3CE2441990EC/SIP/Info/sipSPIValidateGtd: No rawMsg from CCAPI .Aug 28 04:25:58.740: //581/3CE2441990EC/SIP/Info/sipSPIStopHoldTimer: Stopping hold timer .Aug 28 04:25:58.740: //581/3CE2441990EC/SIP/Info/sipSPIStopHoldTimer: Stopping hold timer .Aug 28 04:25:58.744: //581/3CE2441990EC/SIP/Transport/sipSPISendBye: Sending BYE to the transport layer .Aug 28 04:25:58.744: //581/3CE2441990EC/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Global configuration, Switch Transport is FALSE .Aug 28 04:25:58.744: //581/3CE2441990EC/SIP/Transport/sipSPITransportSendMessage: msg=0x83D882C0, addr=192.168.1.10, port=5060, sentBy_port=0, is_req=1, transport=1, switch=0, callBack=0x80AAEE84 .Aug 28 04:25:58.744: //581/3CE2441990EC/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately .Aug 28 04:25:58.744: //581/3CE2441990EC/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0 .Aug 28 04:25:58.744: //581/3CE2441990EC/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x83D882C0 .Aug 28 04:25:58.744: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x83D882C0, addr=192.168.1.10, port=5060, connId=1 for UDP .Aug 28 04:25:58.748: //581/3CE2441990EC/SIP/Info/sentByeDisconnecting: Sent Bye Request, starting DisconnectTimer .Aug 28 04:25:58.748: //581/3CE2441990EC/SIP/State/sipSPIChangeState: 0x83B5DBE4 : State change from (STATE_ACTIVE, SUBSTATE_NONE) to (STATE_DISCONNECTING, SUBSTATE_NONE) .Aug 28 04:25:58.752: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Sent: BYE sip:2155555757@192.168.1.10:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.7:5060;branch=z9hG4bK2E81EA9 From: ;tag=388B59F6-1CF6 To: ;tag=as559decfa Date: Tue, 28 Aug 2012 04:25:52 GMT Call-ID: 3CE68AFA-EFFF11E1-90EFE0FD-8B13B9A1@192.168.1.7 User-Agent: Cisco-SIPGateway/IOS-12.x Max-Forwards: 70 Timestamp: 1346127958 CSeq: 102 BYE Content-Length: 0 .Aug 28 04:25:58.756: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpSocketReads: Msg enqueued for SPI with IP addr: 192.168.1.10:5060 .Aug 28 04:25:58.756: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x83874CDC .Aug 28 04:25:58.756: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: SIP/2.0 481 Call leg/transaction does not exist Via: SIP/2.0/UDP 192.168.1.7:5060;branch=z9hG4bK2E81EA9;received=192.168.1.7;rport=62998 From: ;tag=388B59F6-1CF6 To: ;tag=as559decfa Call-ID: 3CE68AFA-EFFF11E1-90EFE0FD-8B13B9A1@192.168.1.7 CSeq: 102 BYE Server: Asterisk PBX 1.8.15.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 .Aug 28 04:25:58.760: //581/3CE2441990EC/SIP/Info/sipSPIIcpifUpdate: CallState: 3 Playout: 15140 DiscTime:94868386 ConnTime 94865669 .Aug 28 04:25:58.760: //581/3CE2441990EC/SIP/State/sipSPIChangeState: 0x83B5DBE4 : State change from (STATE_DISCONNECTING, SUBSTATE_NONE) to (STATE_DEAD, SUBSTATE_NONE) .Aug 28 04:25:58.760: //581/3CE2441990EC/SIP/Call/sipSPICallInfo: The Call Setup Information is: Call Control Block (CCB) : 0x83B5DBE4 State of The Call : STATE_DEAD TCP Sockets Used : NO Calling Number : 9910 Called Number : 2155555757 Source IP Address (Sig ): 192.168.1.7 Destn SIP Req Addr:Port : 192.168.1.10:5060 Destn SIP Resp Addr:Port : 192.168.1.10:5060 Destination Name : 192.168.1.10 .Aug 28 04:25:58.760: //581/3CE2441990EC/SIP/Call/sipSPIMediaCallInfo: Number of Media Streams: 1 Media Stream : 1 Negotiated Codec : g711ulaw Negotiated Codec Bytes : 160 Negotiated Dtmf-relay : 6 Dtmf-relay Payload : 101 Source IP Address (Media): 192.168.1.7 Source IP Port (Media): 18808 Destn IP Address (Media): 192.168.1.10 Destn IP Port (Media): 28148 Orig Destn IP Address:Port (Media): 0.0.0.0:0 .Aug 28 04:25:58.764: //581/3CE2441990EC/SIP/Call/sipSPICallInfo: Disconnect Cause (CC) : 16 Disconnect Cause (SIP) : 481 .Aug 28 04:25:58.764: //581/3CE2441990EC/SIP/Info/sipSPIUdeleteccCallIdFromTable: Removing call id 245 .Aug 28 04:25:58.764: //581/3CE2441990EC/SIP/Info/sipSPIUdeleteCcbFromUACTable: ****Deleting from UAC table. .Aug 28 04:25:58.764: //581/3CE2441990EC/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x83B5DBE4 key=3CE68AFA-EFFF11E1-90EFE0FD-8B13B9A1@192.168.1.7 .Aug 28 04:25:58.764: //581/3CE2441990EC/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd .Aug 28 04:25:58.768: //581/3CE2441990EC/SIP/Info/sipSPIUfreeOneCCB: Freeing ccb 83B5DBE4