AS5300#debug ccsip all This may severely impact system performance. Continue? [confirm]yAll SIP Call tracing is enabled AS5300# AS5300# AS5300# AS5300# AS5300# AS5300# *Mar 13 14:39:39.711: 0x632D8130 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE) *Mar 13 14:39:39.711: adding call id 14E to table *Mar 13 14:39:39.711: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_SETUP *Mar 13 14:39:39.711: CCSIP-SPI-CONTROL: act_idle_call_setup *Mar 13 14:39:39.711: Using Voice Class Codec, tag = 1 *Mar 13 14:39:39.711: act_idle_call_setup: preferred_codec set[0] type :g711alaw bytes: 160 *Mar 13 14:39:39.711: sipSPICopyPeerDataToCCB: From CLI: Modem NSE payload = 100, Passthrough = 0,Modem relay = 0, Gw-Xid = 1 SPRT latency 200, SPRT Retries = 12, Dict Size = 1024 String Len = 32, Compress dir = 3 *Mar 13 14:39:39.711: sipSPICheckRawMsg: have raw msg from ccapi for type: 102 *Mar 13 14:39:39.711: sipSPICanSetFallbackFlag - Local Fallback is not active *Mar 13 14:39:39.715: Queued event from SIP SPI : SIPSPI_EV_CREATE_CONNECTION *Mar 13 14:39:39.715: 0x632D8130 : State change from (STATE_IDLE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_CONNECTING) *Mar 13 14:39:39.715: 0x632D8130 : State change from (STATE_IDLE, SUBSTATE_CONNECTING) to (STATE_IDLE, SUBSTATE_CONNECTING) *Mar 13 14:39:39.715: ****Adding to UAC table. ccb=0x632D8130 key=253738A2-F04211DC-81719B71-D67790FB@10.0.0.19 *Mar 13 14:39:39.715: sipSPIUsetBillingProfile: sipCallId for billing records = 253738A2-F04211DC-81719B71-D67790FB@10.0.0.19 *Mar 13 14:39:39.715: CCSIP-SPI-CONTROL: act_idle_connection_created *Mar 13 14:39:39.715: CCSIP-SPI-CONTROL: act_idle_connection_created: Connid(1) created to 89.18.32.19:5080, local_port 53942 *Mar 13 14:39:39.715: CCSIP-SPI-CONTROL: sipSPIOutgoingCallSDP *Mar 13 14:39:39.715: sipSPISetMediaSrcAddr: media src addr for stream 1 = 10.0.0.19 *Mar 13 14:39:39.715: sipSPIReserveRtpPort: reserved port 16850 for stream 1 *Mar 13 14:39:39.715: convert_codec_bytes_to_ptime: Values :Codec: g711alaw codecbytes :160, ptime: 20 *Mar 13 14:39:39.719: sip_generate_sdp_xcaps_list: Modem Relay and T38 disabled. X-cap not needed *Mar 13 14:39:39.719: CCSIP-SPI-CONTROL: Clock Time Zone is UTC, same as GMT: Using GMT *Mar 13 14:39:39.719: Received Octet3A=0x83 -> Setting ;screen=yes ;privacy=off *Mar 13 14:39:39.719: sipSPIAddLocalContact *Mar 13 14:39:39.719: Queued event from SIP SPI : SIPSPI_EV_SEND_MESSAGE *Mar 13 14:39:39.719: sip_stats_method *Mar 13 14:39:39.719: sipSPIProcessRtpSessions *Mar 13 14:39:39.719: sipSPIAddStream: Adding stream 1 (callid 334) to the VOIP RTP library *Mar 13 14:39:39.719: sipSPISetMediaSrcAddr: media src addr for stream 1 = 10.0.0.19 *Mar 13 14:39:39.719: sipSPIUpdateRtcpSession: for m-line 1 *Mar 13 14:39:39.719: sipSPIUpdateRtcpSession: rtcp_session info laddr = 10.0.0.19, lport = 16850, raddr = 0.0.0.0, rport=0, do_rtcp=FALSE src_callid = 334, dest_callid = -1, stream type = 1 *Mar 13 14:39:39.723: sipSPIUpdateRtcpSession: No rtp session, creating a new one *Mar 13 14:39:39.723: sipSPIAddStream: AddStream in idle state to open a 'recvonly' media session *Mar 13 14:39:39.723: act_idle_connection_created: Transaction active. Facilities will be queued. *Mar 13 14:39:39.723: 0x632D8130 : State change from (STATE_IDLE, SUBSTATE_CONNECTING) to (STATE_SENT_INVITE, SUBSTATE_NONE) *Mar 13 14:39:39.723: HandleUdpSocketWrites - Using new buffer for sip message *Mar 13 14:39:39.723: Sent: INVITE sip:38514001148@89.18.32.19:5080 SIP/2.0 Via: SIP/2.0/UDP 10.0.0.19:5060;x-route-tag="tgrp:Iskra" From: ;tag=2D49486C-1855 To: Date: Thu, 13 Mar 2008 14:39:39 GMT Call-ID: 253738A2-F04211DC-81719B71-D67790FB@10.0.0.19 Supported: timer,100rel Min-SE: 1800 Cisco-Guid: 624255889-4030861788-2171509617-3598160123 User-Agent: Cisco-SIPGateway/IOS-12.x Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO CSeq: 101 INVITE Max-Forwards: 6 Remote-Party-ID: ;party=calling;screen=yes;privacy=off Timestamp: 1205419179 Contact: Expires: 180 Allow-Events: telephone-event MIME-Version: 1.0 Content-Type: multipart/mixed;boundary=uniqueBoundary Content-Length: 523 --uniqueBoundary Content-Type: application/sdp v=0 o=CiscoSystemsSIP-GW-UserAgent 5947 1401 IN IP4 10.0.0.19 s=SIP Call c=IN IP4 10.0.0.19 t=0 0 m=audio 16850 RTP/AVP 8 c=IN IP4 10.0.0.19 a=rtpmap:8 PCMA/8000 a=ptime:20 --uniqueBoundary Content-Type: application/gtd Content-Disposition: signal;handling=optional IAM, PRN,isdn*,,NET5*, USI,rate,c,3,c,1 USI,lay1,alaw TMR,02 CPN,04,,1,14001148 CGN,04,,1,y,4,13391900 CPC,09 FCI,,,,,,,y, GCI,25356391f04211dc816e9b71d67790fb --uniqueBoundary-- *Mar 13 14:39:39.731: Received: SIP/2.0 415 Unsupported Media Type Via: SIP/2.0/UDP 10.0.0.19:5060;x-route-tag="tgrp:Iskra" From: ;tag=2D49486C-1855 To: ;tag=ag2mFXH0NpctD Call-ID: 253738A2-F04211DC-81719B71-D67790FB@10.0.0.19 CSeq: 101 INVITE Timestamp: 1205419179 0.003927 User-Agent: FreeSWITCH-mod_sofia/1.0.pre3-7870 Accept: application/sdp Accept-Encoding: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, REGISTER, INFO Supported: 100rel, precondition, timer Content-Length: 0 *Mar 13 14:39:39.731: HandleUdpSocketReads :Msg enqueued for SPI with IPaddr: 89.18.32.19:5080 *Mar 13 14:39:39.735: CCSIP-SPI-CONTROL: act_sentinvite_new_message *Mar 13 14:39:39.735: CCSIP-SPI-CONTROL: sipSPICheckResponse *Mar 13 14:39:39.735: sip_stats_status_code *Mar 13 14:39:39.735: Roundtrip delay 16 milliseconds for method INVITE *Mar 13 14:39:39.735: Queued event from SIP SPI : SIPSPI_EV_SEND_MESSAGE *Mar 13 14:39:39.735: sip_stats_method *Mar 13 14:39:39.735: ccsip_set_release_source_for_peer:ownCallId[334], src[4] *Mar 13 14:39:39.735: sipSPIHandleUnsupportedMedia: Remote end does not support multipart bodies. Sending only SDP body. *Mar 13 14:39:39.735: RequestCloseConnection: Closing connid 1 Local Port 53942 *Mar 13 14:39:39.735: Queued event from SIP SPI : SIPSPI_EV_CLOSE_CONNECTION *Mar 13 14:39:39.735: Queued event from SIP SPI : SIPSPI_EV_CREATE_CONNECTION *Mar 13 14:39:39.735: 0x632D8130 : State change from (STATE_SENT_INVITE, SUBSTATE_NONE) to (STATE_SENT_INVITE, SUBSTATE_CONNECTING) *Mar 13 14:39:39.735: 0x632D8130 : State change from (STATE_SENT_INVITE, SUBSTATE_CONNECTING) to (STATE_IDLE, SUBSTATE_CONNECTING) *Mar 13 14:39:39.739: Sent: ACK sip:38514001148@89.18.32.19:5080 SIP/2.0 Via: SIP/2.0/UDP 10.0.0.19:5060;x-route-tag="tgrp:Iskra" From: ;tag=2D49486C-1855 To: ;tag=ag2mFXH0NpctD Date: Thu, 13 Mar 2008 14:39:39 GMT Call-ID: 253738A2-F04211DC-81719B71-D67790FB@10.0.0.19 Max-Forwards: 6 Content-Length: 0 CSeq: 101 ACK *Mar 13 14:39:39.739: udpsock_close_connect: Socket fd: 1 closed for connid 1 with remote port: 5080 *Mar 13 14:39:39.739: CCSIP-SPI-CONTROL: act_idle_connection_created *Mar 13 14:39:39.739: CCSIP-SPI-CONTROL: act_idle_connection_created: Connid(1) created to 89.18.32.19:5080, local_port 55870 *Mar 13 14:39:39.739: CCSIP-SPI-CONTROL: Clock Time Zone is UTC, same as GMT: Using GMT *Mar 13 14:39:39.739: Received Octet3A=0x83 -> Setting ;screen=yes ;privacy=off *Mar 13 14:39:39.739: sipSPIAddLocalContact *Mar 13 14:39:39.743: Queued event from SIP SPI : SIPSPI_EV_SEND_MESSAGE *Mar 13 14:39:39.743: sip_stats_method *Mar 13 14:39:39.743: sipSPIProcessRtpSessions *Mar 13 14:39:39.743: sipSPIAddStream: Adding stream 1 (callid 334) to the VOIP RTP library *Mar 13 14:39:39.743: sipSPISetMediaSrcAddr: media src addr for stream 1 = 10.0.0.19 *Mar 13 14:39:39.743: sipSPIUpdateRtcpSession: for m-line 1 *Mar 13 14:39:39.743: sipSPIUpdateRtcpSession: rtcp_session info laddr = 10.0.0.19, lport = 16850, raddr = 0.0.0.0, rport=0, do_rtcp=FALSE src_callid = 334, dest_callid = -1, stream type = 1 *Mar 13 14:39:39.743: sipSPIUpdateRtcpSession rtp session already created - update *Mar 13 14:39:39.743: sipSPIAddStream: AddStream in idle state to open a 'recvonly' media session *Mar 13 14:39:39.743: act_idle_connection_created: Transaction active. Facilities will be queued. *Mar 13 14:39:39.743: 0x632D8130 : State change from (STATE_IDLE, SUBSTATE_CONNECTING) to (STATE_SENT_INVITE, SUBSTATE_NONE) *Mar 13 14:39:39.743: Sent: INVITE sip:38514001148@89.18.32.19:5080 SIP/2.0 Via: SIP/2.0/UDP 10.0.0.19:5060;x-route-tag="tgrp:Iskra" From: ;tag=2D49486C-1855 To: Date: Thu, 13 Mar 2008 14:39:39 GMT Call-ID: 253738A2-F04211DC-81719B71-D67790FB@10.0.0.19 Supported: timer,100rel Min-SE: 1800 Cisco-Guid: 624255889-4030861788-2171509617-3598160123 User-Agent: Cisco-SIPGateway/IOS-12.x Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO CSeq: 102 INVITE Max-Forwards: 6 Remote-Party-ID: ;party=calling;screen=yes;privacy=off Timestamp: 1205419179 Contact: Expires: 180 Allow-Events: telephone-event Content-Type: application/sdp Content-Length: 182 v=0 o=CiscoSystemsSIP-GW-UserAgent 5947 1401 IN IP4 10.0.0.19 s=SIP Call c=IN IP4 10.0.0.19 t=0 0 m=audio 16850 RTP/AVP 8 c=IN IP4 10.0.0.19 a=rtpmap:8 PCMA/8000 a=ptime:20 *Mar 13 14:39:39.751: Received: SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.0.0.19:5060;x-route-tag="tgrp:Iskra" From: ;tag=2D49486C-1855 To: Call-ID: 253738A2-F04211DC-81719B71-D67790FB@10.0.0.19 CSeq: 102 INVITE Timestamp: 1205419179 0.007713 User-Agent: FreeSWITCH-mod_sofia/1.0.pre3-7870 Content-Length: 0 *Mar 13 14:39:39.755: HandleUdpSocketReads :Msg enqueued for SPI with IPaddr: 89.18.32.19:5080 *Mar 13 14:39:39.755: CCSIP-SPI-CONTROL: act_sentinvite_new_message *Mar 13 14:39:39.755: CCSIP-SPI-CONTROL: sipSPICheckResponse *Mar 13 14:39:39.755: sip_stats_status_code *Mar 13 14:39:39.755: Roundtrip delay 16 milliseconds for method INVITE *Mar 13 14:39:39.755: 0x632D8130 : State change from (STATE_SENT_INVITE, SUBSTATE_NONE) to (STATE_RECD_PROCEEDING, SUBSTATE_PROCEEDING_PROCEEDING) *Mar 13 14:39:40.499: Received: SIP/2.0 415 Unsupported Media Type Via: SIP/2.0/UDP 10.0.0.19:5060;x-route-tag="tgrp:Iskra" From: ;tag=2D49486C-1855 To: ;tag=ag2mFXH0NpctD Call-ID: 253738A2-F04211DC-81719B71-D67790FB@10.0.0.19 CSeq: 101 INVITE Timestamp: 1205419179 0.003927 User-Agent: FreeSWITCH-mod_sofia/1.0.pre3-7870 Accept: application/sdp Accept-Encoding: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, REGISTER, INFO Supported: 100rel, precondition, timer Content-Length: 0 *Mar 13 14:39:40.499: HandleUdpSocketReads :Msg enqueued for SPI with IPaddr: 89.18.32.19:5080 *Mar 13 14:39:40.499: CCSIP-SPI-CONTROL: act_recdproc_new_message *Mar 13 14:39:40.499: CCSIP-SPI-CONTROL: act_recdproc_new_message_response *Mar 13 14:39:40.499: CCSIP-SPI-CONTROL: sipSPICheckResponse *Mar 13 14:39:40.499: CCSIP-SPI-CONTROL: sipSPICheckResponse : Bad cseq number *Mar 13 14:39:40.499: CCSIP-SPI-CONTROL: act_recdproc_new_message_response : Check Response Failed *Mar 13 14:39:40.663: Received: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.0.0.19:5060;x-route-tag="tgrp:Iskra" From: ;tag=2D49486C-1855 To: ;tag=BSUDHr23jZ2cS Call-ID: 253738A2-F04211DC-81719B71-D67790FB@10.0.0.19 CSeq: 102 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.0.pre3-7870 Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, REGISTER, INFO Supported: 100rel, precondition, timer Content-Length: 0 *Mar 13 14:39:40.663: HandleUdpSocketReads :Msg enqueued for SPI with IPaddr: 89.18.32.19:5080 *Mar 13 14:39:40.663: CCSIP-SPI-CONTROL: act_recdproc_new_message *Mar 13 14:39:40.663: CCSIP-SPI-CONTROL: act_recdproc_new_message_response *Mar 13 14:39:40.663: CCSIP-SPI-CONTROL: sipSPICheckResponse *Mar 13 14:39:40.663: sip_stats_status_code *Mar 13 14:39:40.663: Roundtrip delay 924 milliseconds for method INVITE *Mar 13 14:39:40.663: CCSIP-SPI-CONTROL: act_recdproc_new_message_response : Early media disabled for 180: Ignoring SDP if present *Mar 13 14:39:40.663: HandleSIP1xxRinging: SDP in 180 will be ignored if present: No early media cut through *Mar 13 14:39:40.663: HandleSIP1xxRinging: SDP Body either absent or ignored in 180 RINGING:- would wait for 200 OK to do negotiation. *Mar 13 14:39:40.663: HandleSIP1xxRinging: MediaNegotiation expected in 200 OK *Mar 13 14:39:40.667: sipSPICreateRawMsg: No GTD passed. *Mar 13 14:39:40.667: 0x632D8130 : State change from (STATE_RECD_PROCEEDING, SUBSTATE_PROCEEDING_PROCEEDING) to (STATE_RECD_PROCEEDING, SUBSTATE_PROCEEDING_ALERTING) *Mar 13 14:39:40.667: HandleSIP1xxRinging: Transaction Complete. Lock on Facilities released. *Mar 13 14:39:40.667: CCSIP-SPI-CONTROL: ccsip_bridge: confID = 121, srcCallID = 334, dstCallID = 333 *Mar 13 14:39:40.667: sipSPIUupdateCcCallIds: old src/dest ccCallids: -1/-1, new src/dest ccCallids: 334/333 *Mar 13 14:39:40.667: sipSPIUupdateCcCallIds: old streamcallid=334, new streamcallid=334 *Mar 13 14:39:40.667: CCSIP-SPI-CONTROL: ccsip_caps_ind *Mar 13 14:39:40.667: ccsip_caps_ind: Load DSP with preferred codec : g711alaw, Bytes=160 *Mar 13 14:39:40.667: ccsip_caps_ind: set forking flag to 0x0 *Mar 13 14:39:40.667: sip_set_modem_caps: Preferred (or the one that came from DSM) modem relay=1, from CLI config=0 *Mar 13 14:39:40.667: sip_set_modem_caps: Disabling Modem Relay... *Mar 13 14:39:40.667: sip_set_modem_caps: Negotiation NOT yet Done. Set the configured values *Mar 13 14:39:40.667: sip_set_modem_caps: Modem Relay & Passthru both disabled *Mar 13 14:39:40.667: sip_set_modem_caps: nse payload = 100, ptru mode = 0, ptru-codec=0, redundancy=0, xid=1, relay=0, sprt-retry=12, latecncy=200, compres-dir=3, dict=1024, strnlen=32 *Mar 13 14:39:40.667: sipSPISetStreamInfo: num_streams = 1 *Mar 13 14:39:40.667: sipSPISetStreamInfo: adding stream type 1 from mline 1 *Mar 13 14:39:40.667: sipSPISetStreamInfo: caps.stream_count=1, caps.stream[0].stream_type=0x2, caps.stream_list.xmitFunc=voip_rtp_xmit, caps.stream_list.context=0x63495DA8 (gccb) *Mar 13 14:39:40.671: ccsip_caps_ind: Load DSP with codec : g711alaw, Bytes=160 *Mar 13 14:39:40.671: CCSIP-SPI-CONTROL: ccsip_caps_ack *Mar 13 14:39:40.671: ccsip_caps_ack: set forking flag to 0x7 *Mar 13 14:39:41.207: Received: SIP/2.0 415 Unsupported Media Type Via: SIP/2.0/UDP 10.0.0.19:5060;x-route-tag="tgrp:Iskra" From: ;tag=2D49486C-1855 To: ;tag=ag2mFXH0NpctD Call-ID: 253738A2-F04211DC-81719B71-D67790FB@10.0.0.19 CSeq: 101 INVITE Timestamp: 1205419179 0.003927 User-Agent: FreeSWITCH-mod_sofia/1.0.pre3-7870 Accept: application/sdp Accept-Encoding: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, REGISTER, INFO Supported: 100rel, precondition, timer Content-Length: 0 *Mar 13 14:39:41.207: HandleUdpSocketReads :Msg enqueued for SPI with IPaddr: 89.18.32.19:5080 *Mar 13 14:39:41.207: CCSIP-SPI-CONTROL: act_recdproc_new_message *Mar 13 14:39:41.207: CCSIP-SPI-CONTROL: act_recdproc_new_message_response *Mar 13 14:39:41.207: CCSIP-SPI-CONTROL: sipSPICheckResponse *Mar 13 14:39:41.207: CCSIP-SPI-CONTROL: sipSPICheckResponse : Bad cseq number *Mar 13 14:39:41.207: CCSIP-SPI-CONTROL: act_recdproc_new_message_response : Check Response Failed *Mar 13 14:39:43.711: Received: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.0.0.19:5060;x-route-tag="tgrp:Iskra" From: ;tag=2D49486C-1855 To: ;tag=BSUDHr23jZ2cS Call-ID: 253738A2-F04211DC-81719B71-D67790FB@10.0.0.19 CSeq: 102 INVITE Contact: User-Agent: FreeSWITCH-mod_sofia/1.0.pre3-7870 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, REGISTER, INFO Supported: 100rel, precondition, timer Min-SE: 1800 Content-Type: application/sdp Content-Disposition: session Content-Length: 272 v=0 o=FreeSWITCH 8367682047008151068 7117515538434833209 IN IP4 89.18.32.19 s=FreeSWITCH c=IN IP4 89.18.32.19 t=0 0 a=sendrecv m=audio 16614 RTP/AVP 8 101 13 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=rtpmap:13 CN/8000 a=ptime:20 *Mar 13 14:39:43.711: HandleUdpSocketReads :Msg enqueued for SPI with IPaddr: 89.18.32.19:5080 *Mar 13 14:39:43.711: ***creating child CCB 0 *Mar 13 14:39:43.711: ***Updating child CCB *Mar 13 14:39:43.711: adding call id 14F to table *Mar 13 14:39:43.711: CCSIP-SPI-CONTROL: act_recdproc_new_message *Mar 13 14:39:43.711: CCSIP-SPI-CONTROL: act_recdproc_new_message_response *Mar 13 14:39:43.711: CCSIP-SPI-CONTROL: sipSPICheckResponse *Mar 13 14:39:43.715: sip_stats_status_code *Mar 13 14:39:43.715: Roundtrip delay 759781384 milliseconds for method INVITE *Mar 13 14:39:43.715: act_recdproc_new_message_response: Transaction active. Facilities will be queued. *Mar 13 14:39:43.715: CCSIP-SPI-CONTROL: sipSPIUACSessionTimer *Mar 13 14:39:43.715: sipSPIGetGtdBody: No valid GTD body found. *Mar 13 14:39:43.715: CCSIP-SPI-CONTROL: act_recdproc_continue_200_processing *Mar 13 14:39:43.715: CCSIP-SPI-CONTROL: act_recdproc_continue_200_processing: *** This ccb is a child *Mar 13 14:39:43.715: Removing call id 14E *Mar 13 14:39:43.715: sipSPIUupdateCcCallIds: old src/dest ccCallids: -1/333, new src/dest ccCallids: 334/333 *Mar 13 14:39:43.715: sipSPIUupdateCcCallIds: old streamcallid=334, new streamcallid=334 *Mar 13 14:39:43.715: sipSPIMakeChildParentCCB: skipping assignment of context ptr *Mar 13 14:39:43.715: ****Deleting from UAC table. ccb=0x632D8130 key=253738A2-F04211DC-81719B71-D67790FB@10.0.0.19 *Mar 13 14:39:43.715: CCSIP-SPI-CONTROL: sipSPICallCleanup *Mar 13 14:39:43.715: ***freeing parent ccb 632D8130 *Mar 13 14:39:43.715: Removing call id 14E *Mar 13 14:39:43.715: sipSPIUdeleteccCallIdFromTable: Entry not found for ccCallId *Mar 13 14:39:43.715: sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd *Mar 13 14:39:43.715: freeing ccb 632D8130 *Mar 13 14:39:43.715: adding call id 14E to table *Mar 13 14:39:43.715: ****Adding to UAC table. ccb=0x632D909C key=253738A2-F04211DC-81719B71-D67790FB@10.0.0.19 *Mar 13 14:39:43.719: sipSPICompareRespMediaInfo *Mar 13 14:39:43.719: sipSPICompareRespMediaInfo No Comparsion needed as 18x response SDP is either absent or ignored *Mar 13 14:39:43.719: sipSPIDoMediaNegotiation: number of m lines is 1 *Mar 13 14:39:43.719: sipSPIDoAudioNegotiation: Codec (g711alaw) Negotiation Successful on Static Payload for m-line 1 *Mar 13 14:39:43.719: sipSPIDoPtimeNegotiation: One ptime attribute found - value:20 *Mar 13 14:39:43.719: convert_ptime_to_codec_bytes: Values :Codec: g711alaw ptime :20, codecbytes: 160 *Mar 13 14:39:43.719: convert_codec_bytes_to_ptime: Values :Codec: g711alaw codecbytes :160, ptime: 20 *Mar 13 14:39:43.719: sipSPIDoDTMFRelayNegotiation: m-line index 1 *Mar 13 14:39:43.719: sipSPIDoDTMFRelayNegotiation: Requested DTMF-RELAY option(s) not found in Preferred DTMF-RELAY option list! *Mar 13 14:39:43.719: sipSPIStreamTypeAndDtmfRelay: DTMF Relay mode : Inband Voice *Mar 13 14:39:43.719: sip_sdp_get_modem_relay_cap_params: *Mar 13 14:39:43.719: sip_sdp_get_modem_relay_cap_params: NSE payload from X-cap = 0 *Mar 13 14:39:43.719: sip_do_nse_negotiation: SDP not present. Use local NSE payload 100. *Mar 13 14:39:43.719: sip_select_modem_relay_params: X-tmr not present in SDP. Disable modem relay *Mar 13 14:39:43.719: sipSPIGetSDPDirectionAttribute: No direction attribute present or multiple direction attributes that can't be handled for m-line:1 and num-a-lines:0 *Mar 13 14:39:43.719: sipSPIDoAudioNegotiation: Codec negotiation successful for media line 1 payload_type=8, codec_bytes=160, codec=g711alaw, dtmf_relay=inband-voice stream_type=voice-only (0), dest_ip_address=89.18.32.19, dest_port=16614 *Mar 13 14:39:43.719: sipSPIReplaceSDP *Mar 13 14:39:43.719: sipSPICopySdpInfo *Mar 13 14:39:43.719: sipSPIUpdCallWithSdpInfo: Preferred Codec : g711alaw, bytes :160 Preferred DTMF relay : inband-voice Preferred NTE payload : 101 Early Media : No Delayed Media : No Bridge Done : Yes New Media : No DSP DNLD Reqd : Yes *Mar 13 14:39:43.719: sipSPISetMediaSrcAddr: media src addr for stream 1 = 10.0.0.19 *Mar 13 14:39:43.719: sipSPIUpdCallWithSdpInfo:Stream Type:0 M-line Index : 1 State : STREAM_ADDING (2) Callid : 334 Negotiated Codec : g711alaw, bytes :160 Negotiated DTMF relay : inband-voice Negotiated NTE payload : 0 Negotiated CN payload : 0 Media Srce Addr/Port : 10.0.0.19:16850 Media Dest Addr/Port : 89.18.32.19:16614 *Mar 13 14:39:43.719: sipSPIProcessMediaChanges *Mar 13 14:39:43.719: sipSPIProcessMediaChanges DSPDNLD Reqd is true. Call DoCapsInd *Mar 13 14:39:43.723: CCSIP-SPI-CONTROL: ccsip_do_caps_ind *Mar 13 14:39:43.723: ccsip_get_rtcp_session_parameters: CURRENT VALUES: stream_callid=334, current_seq_num=0x119 *Mar 13 14:39:43.723: ccsip_get_rtcp_session_parameters: NEW VALUES: stream_callid=334, current_seq_num=0xCC1 *Mar 13 14:39:43.723: ccsip_do_caps_ind: Load DSP with codec: g711alaw, Bytes=160 *Mar 13 14:39:43.723: sipSPISetStreamInfo: num_streams = 0 *Mar 13 14:39:43.723: sipSPISetStreamInfo: ERROR - number of active streams is zero (0)! *Mar 13 14:39:43.723: sipSPISetStreamInfo: caps.stream_count=0, caps.stream[0].stream_type=0xFFFF, caps.stream_list.xmitFunc=??unknown??, caps.stream_list.context=0x0 (rtp_fork_id) *Mar 13 14:39:43.723: sipSPISetDTMFRelayMode: set DSP for dtmf-relay = CC_CAP_DTMF_RELAY_INBAND_VOICE_AND_OOB *Mar 13 14:39:43.723: sip_set_modem_caps: Preferred (or the one that came from DSM) modem relay=0, from CLI config=0 *Mar 13 14:39:43.723: sip_set_modem_caps: Disabling Modem Relay... *Mar 13 14:39:43.723: sip_set_modem_caps: Negotiation already Done. Set negotiated Modem caps *Mar 13 14:39:43.723: sip_set_modem_caps: Modem Relay & Passthru both disabled *Mar 13 14:39:43.723: sip_set_modem_caps: nse payload = 100, ptru mode = 0, ptru-codec=0, redundancy=0, xid=0, relay=0, sprt-retry=12, latecncy=200, compres-dir=3, dict=1024, strnlen=32 *Mar 13 14:39:43.723: ccsip_process_response_contact_record_route *Mar 13 14:39:43.723: 0x632D909C : State change from (STATE_RECD_PROCEEDING, SUBSTATE_NONE) to (STATE_RECD_PROCEEDING, SUBSTATE_CONNECTING) *Mar 13 14:39:43.723: Queued event from SIP SPI : SIPSPI_EV_CREATE_CONNECTION *Mar 13 14:39:43.723: 0x632D909C : State change from (STATE_RECD_PROCEEDING, SUBSTATE_CONNECTING) to (STATE_RECD_PROCEEDING, SUBSTATE_CONNECTING) *Mar 13 14:39:43.723: CCSIP-SPI-CONTROL: ccsip_caps_ack *Mar 13 14:39:43.723: ccsip_caps_ack: set forking flag to 0x7 *Mar 13 14:39:43.727: CCSIP-SPI-CONTROL: act_recdproc_connection_created *Mar 13 14:39:43.727: CCSIP-SPI-CONTROL: sipSPICheckSocketConnection: Connid(2) created to 89.18.32.19:5080, local_port 58463 *Mar 13 14:39:43.727: 0x632D909C : State change from (STATE_RECD_PROCEEDING, SUBSTATE_CONNECTING) to (STATE_RECD_PROCEEDING, SUBSTATE_NONE) *Mar 13 14:39:43.727: CCSIP-SPI-CONTROL: sipSPIProcess200OKforinvite *Mar 13 14:39:43.727: sipSPICreateRawMsg: No GTD passed. *Mar 13 14:39:43.727: RequestCloseConnection: Closing connid 1 Local Port 0 *Mar 13 14:39:43.727: Queued event from SIP SPI : SIPSPI_EV_CLOSE_CONNECTION *Mar 13 14:39:43.727: Queued event from SIP SPI : SIPSPI_EV_SEND_MESSAGE *Mar 13 14:39:43.727: sip_stats_method *Mar 13 14:39:43.727: 0x632D909C : State change from (STATE_RECD_PROCEEDING, SUBSTATE_NONE) to (STATE_ACTIVE, SUBSTATE_NONE) *Mar 13 14:39:43.727: The Call Setup Information is : Call Control Block (CCB) : 0x632D909C State of The Call : STATE_ACTIVE TCP Sockets Used : NO Calling Number : 38513391900 Called Number : 38514001148 Number of Media Streams : 1 *Mar 13 14:39:43.727: Media Stream 1 Negotiated Codec : g711alaw Negotiated Codec Bytes : 160 Negotiated Dtmf-relay : 0 Dtmf-relay Payload : 0 Source IP Address (Media): 10.0.0.19 Source IP Port (Media): 16850 Destn IP Address (Media): 89.18.32.19 Destn IP Port (Media): 16614 *Mar 13 14:39:43.727: Orig Destn IP Address:Port (Media): 0.0.0.0:0 *Mar 13 14:39:43.731: Source IP Address (Sig ): 10.0.0.19 Destn SIP Req Addr:Port : 89.18.32.19:5080 Destn SIP Resp Addr:Port : 0.0.0.0:0 Destination Name : *Mar 13 14:39:43.731: sipSPIProcess200OKforinvite: Transaction Complete. Lock on Facilities released. *Mar 13 14:39:43.731: sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd *Mar 13 14:39:43.731: udpsock_close_connect: Socket fd: 1 closed for connid 1 with remote port: 5080 *Mar 13 14:39:43.731: Sent: ACK sip:mod_sofia@89.18.32.19:5080;transport=udp SIP/2.0 Via: SIP/2.0/UDP 10.0.0.19:5060 From: ;tag=2D49486C-1855 To: ;tag=BSUDHr23jZ2cS Date: Thu, 13 Mar 2008 14:39:39 GMT Call-ID: 253738A2-F04211DC-81719B71-D67790FB@10.0.0.19 Max-Forwards: 6 Content-Length: 0 CSeq: 102 ACK *Mar 13 14:39:44.591: Received: SIP/2.0 415 Unsupported Media Type Via: SIP/2.0/UDP 10.0.0.19:5060;x-route-tag="tgrp:Iskra" From: ;tag=2D49486C-1855 To: ;tag=ag2mFXH0NpctD Call-ID: 253738A2-F04211DC-81719B71-D67790FB@10.0.0.19 CSeq: 101 INVITE Timestamp: 1205419179 0.003927 User-Agent: FreeSWITCH-mod_sofia/1.0.pre3-7870 Accept: application/sdp Accept-Encoding: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, REGISTER, INFO Supported: 100rel, precondition, timer Content-Length: 0 *Mar 13 14:39:44.591: HandleUdpSocketReads :Msg enqueued for SPI with IPaddr: 89.18.32.19:5080 *Mar 13 14:39:44.595: CCSIP-SPI-CONTROL: sipSPICheckFromToResponse: Compare From/To failed - IGNORE IF HAIRPIN CALL *Mar 13 14:39:44.595: ccsip_spi_process_event:Could not find ccb for response *Mar 13 14:39:48.171: Received: SIP/2.0 415 Unsupported Media Type Via: SIP/2.0/UDP 10.0.0.19:5060;x-route-tag="tgrp:Iskra" From: ;tag=2D49486C-1855 To: ;tag=ag2mFXH0NpctD Call-ID: 253738A2-F04211DC-81719B71-D67790FB@10.0.0.19 CSeq: 101 INVITE Timestamp: 1205419179 0.003927 User-Agent: FreeSWITCH-mod_sofia/1.0.pre3-7870 Accept: application/sdp Accept-Encoding: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, REGISTER, INFO Supported: 100rel, precondition, timer Content-Length: 0 *Mar 13 14:39:48.171: HandleUdpSocketReads :Msg enqueued for SPI with IPaddr: 89.18.32.19:5080 *Mar 13 14:39:48.171: CCSIP-SPI-CONTROL: sipSPICheckFromToResponse: Compare From/To failed - IGNORE IF HAIRPIN CALL *Mar 13 14:39:48.171: ccsip_spi_process_event:Could not find ccb for response *Mar 13 14:39:49.747: %ISDN-6-CONNECT: Interface Serial1:30 is now connected to 13391900 unknown *Mar 13 14:39:50.319: Received: SIP/2.0 415 Unsupported Media Type Via: SIP/2.0/UDP 10.0.0.19:5060;x-route-tag="tgrp:Iskra" From: ;tag=2D49486C-1855 To: ;tag=ag2mFXH0NpctD Call-ID: 253738A2-F04211DC-81719B71-D67790FB@10.0.0.19 CSeq: 101 INVITE Timestamp: 1205419179 0.003927 User-Agent: FreeSWITCH-mod_sofia/1.0.pre3-7870 Accept: application/sdp Accept-Encoding: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, REGISTER, INFO Supported: 100rel, precondition, timer Content-Length: 0 *Mar 13 14:39:50.323: HandleUdpSocketReads :Msg enqueued for SPI with IPaddr: 89.18.32.19:5080 *Mar 13 14:39:50.323: CCSIP-SPI-CONTROL: sipSPICheckFromToResponse: Compare From/To failed - IGNORE IF HAIRPIN CALL *Mar 13 14:39:50.323: ccsip_spi_process_event:Could not find ccb for response *Mar 13 14:39:50.719: Received: BYE sip:38513391900@10.0.0.19:5060 SIP/2.0 Via: SIP/2.0/UDP 89.18.32.19:5080;rport;branch=z9hG4bK71yv201UjDa8K Max-Forwards: 70 From: ;tag=BSUDHr23jZ2cS To: ;tag=2D49486C-1855 Call-ID: 253738A2-F04211DC-81719B71-D67790FB@10.0.0.19 CSeq: 96584005 BYE Contact: User-Agent: FreeSWITCH-mod_sofia/1.0.pre3-7870 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, REGISTER, INFO Supported: 100rel, precondition, timer Reason: Q.850;cause=16;text="NORMAL_CLEARING" Content-Length: 0 *Mar 13 14:39:50.719: HandleUdpSocketReads :Msg enqueued for SPI with IPaddr: 89.18.32.19:5080 *Mar 13 14:39:50.719: ****Found CCB in UAC table *Mar 13 14:39:50.719: CCSIP-SPI-CONTROL: act_active_new_message *Mar 13 14:39:50.719: CCSIP-SPI-CONTROL: sact_active_new_message_request *Mar 13 14:39:50.719: CCSIP-SPI-CONTROL: Clock Time Zone is UTC, same as GMT: Using GMT *Mar 13 14:39:50.719: sip_stats_method *Mar 13 14:39:50.719: ccsip_set_release_source_for_peer:ownCallId[334], src[4] *Mar 13 14:39:50.719: sipSPIStopHoldTimer: Stopping hold timer *Mar 13 14:39:50.723: Queued event from SIP SPI : SIPSPI_EV_SEND_MESSAGE *Mar 13 14:39:50.723: sip_stats_status_code *Mar 13 14:39:50.723: CCSIP-SPI-CONTROL: sipSPIInitiateCallDisconnect : Initiate call disconnect(16) for outgoing call *Mar 13 14:39:50.723: 0x632D909C : State change from (STATE_ACTIVE, SUBSTATE_NONE) to (STATE_DISCONNECTING, SUBSTATE_NONE) *Mar 13 14:39:50.723: Sent: SIP/2.0 200 OK Via: SIP/2.0/UDP 89.18.32.19:5080;rport;branch=z9hG4bK71yv201UjDa8K From: ;tag=BSUDHr23jZ2cS To: ;tag=2D49486C-1855 Date: Thu, 13 Mar 2008 14:39:50 GMT Call-ID: 253738A2-F04211DC-81719B71-D67790FB@10.0.0.19 Server: Cisco-SIPGateway/IOS-12.x Content-Length: 0 CSeq: 96584005 BYE *Mar 13 14:39:50.723: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_DISCONNECT *Mar 13 14:39:50.727: CCSIP-SPI-CONTROL: act_disconnecting_disconnect *Mar 13 14:39:50.727: CCSIP-SPI-CONTROL: sipSPICallCleanup *Mar 13 14:39:50.727: sipSPIIcpifUpdate :CallState: 4 Playout: 0 DiscTime:75978839 ConnTime 75978139 *Mar 13 14:39:50.727: 0x632D909C : State change from (STATE_DISCONNECTING, SUBSTATE_NONE) to (STATE_DEAD, SUBSTATE_NONE) *Mar 13 14:39:50.727: The Call Setup Information is : Call Control Block (CCB) : 0x632D909C State of The Call : STATE_DEAD TCP Sockets Used : NO Calling Number : 38513391900 Called Number : 38514001148 Number of Media Streams : 1 *Mar 13 14:39:50.727: Media Stream 1 Negotiated Codec : g711alaw Negotiated Codec Bytes : 160 Negotiated Dtmf-relay : 0 Dtmf-relay Payload : 0 Source IP Address (Media): 10.0.0.19 Source IP Port (Media): 16850 Destn IP Address (Media): 89.18.32.19 Destn IP Port (Media): 16614 *Mar 13 14:39:50.727: Orig Destn IP Address:Port (Media): 0.0.0.0:0 *Mar 13 14:39:50.727: Source IP Address (Sig ): 10.0.0.19 Destn SIP Req Addr:Port : 89.18.32.19:5080 Destn SIP Resp Addr:Port : 89.18.32.19:5080 Destination Name : *Mar 13 14:39:50.727: Disconnect Cause (CC) : 16 Disconnect Cause (SIP) : 200 *Mar 13 14:39:50.727: ****Deleting from UAC table. ccb=0x632D909C key=253738A2-F04211DC-81719B71-D67790FB@10.0.0.19 *Mar 13 14:39:50.727: Removing call id 14E *Mar 13 14:39:50.731: Removing call id 14F *Mar 13 14:39:50.731: RequestCloseConnection: Closing connid 2 Local Port 58463 *Mar 13 14:39:50.731: Queued event from SIP SPI : SIPSPI_EV_CLOSE_CONNECTION *Mar 13 14:39:50.731: sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd *Mar 13 14:39:50.731: freeing ccb 632D909C *Mar 13 14:39:50.731: udpsock_close_connect: Socket fd: 2 closed for connid 2 with remote port: 5080 *Mar 13 14:39:50.735: %ISDN-6-DISCONNECT: Interface Serial1:30 disconnected from 13391900 , call lasted 6 seconds *Mar 13 14:39:55.279: Received: SIP/2.0 415 Unsupported Media Type Via: SIP/2.0/UDP 10.0.0.19:5060;x-route-tag="tgrp:Iskra" From: ;tag=2D49486C-1855 To: ;tag=ag2mFXH0NpctD Call-ID: 253738A2-F04211DC-81719B71-D67790FB@10.0.0.19 CSeq: 101 INVITE Timestamp: 1205419179 0.003927 User-Agent: FreeSWITCH-mod_sofia/1.0.pre3-7870 Accept: application/sdp Accept-Encoding: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, REGISTER, INFO Supported: 100rel, precondition, timer Content-Length: 0 *Mar 13 14:39:55.279: HandleUdpSocketReads :Msg enqueued for SPI with IPaddr: 89.18.32.19:5080 *Mar 13 14:39:55.279: ccsip_spi_process_event:Could not find ccb for response *Mar 13 14:39:58.551: Received: SIP/2.0 415 Unsupported Media Type Via: SIP/2.0/UDP 10.0.0.19:5060;x-route-tag="tgrp:Iskra" From: ;tag=2D49486C-1855 To: ;tag=ag2mFXH0NpctD Call-ID: 253738A2-F04211DC-81719B71-D67790FB@10.0.0.19 CSeq: 101 INVITE Timestamp: 1205419179 0.003927 User-Agent: FreeSWITCH-mod_sofia/1.0.pre3-7870 Accept: application/sdp Accept-Encoding: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, REGISTER, INFO Supported: 100rel, precondition, timer Content-Length: 0 *Mar 13 14:39:58.555: HandleUdpSocketReads :Msg enqueued for SPI with IPaddr: 89.18.32.19:5080 *Mar 13 14:39:58.555: ccsip_spi_process_event:Could not find ccb for response *Mar 13 14:40:03.651: Received: SIP/2.0 415 Unsupported Media Type Via: SIP/2.0/UDP 10.0.0.19:5060;x-route-tag="tgrp:Iskra" From: ;tag=2D49486C-1855 To: ;tag=ag2mFXH0NpctD Call-ID: 253738A2-F04211DC-81719B71-D67790FB@10.0.0.19 CSeq: 101 INVITE Timestamp: 1205419179 0.003927 User-Agent: FreeSWITCH-mod_sofia/1.0.pre3-7870 Accept: application/sdp Accept-Encoding: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, REGISTER, INFO Supported: 100rel, precondition, timer Content-Length: 0 *Mar 13 14:40:03.651: HandleUdpSocketReads :Msg enqueued for SPI with IPaddr: 89.18.32.19:5080 *Mar 13 14:40:03.655: ccsip_spi_process_event:Could not find ccb for response *Mar 13 14:40:06.663: Received: SIP/2.0 415 Unsupported Media Type Via: SIP/2.0/UDP 10.0.0.19:5060;x-route-tag="tgrp:Iskra" From: ;tag=2D49486C-1855 To: ;tag=ag2mFXH0NpctD Call-ID: 253738A2-F04211DC-81719B71-D67790FB@10.0.0.19 CSeq: 101 INVITE Timestamp: 1205419179 0.003927 User-Agent: FreeSWITCH-mod_sofia/1.0.pre3-7870 Accept: application/sdp Accept-Encoding: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, REGISTER, INFO Supported: 100rel, precondition, timer Content-Length: 0 *Mar 13 14:40:06.663: HandleUdpSocketReads :Msg enqueued for SPI with IPaddr: 89.18.32.19:5080 *Mar 13 14:40:06.667: ccsip_spi_process_event:Could not find ccb for response *Mar 13 14:40:10.431: Received: SIP/2.0 415 Unsupported Media Type Via: SIP/2.0/UDP 10.0.0.19:5060;x-route-tag="tgrp:Iskra" From: ;tag=2D49486C-1855 To: ;tag=ag2mFXH0NpctD Call-ID: 253738A2-F04211DC-81719B71-D67790FB@10.0.0.19 CSeq: 101 INVITE Timestamp: 1205419179 0.003927 User-Agent: FreeSWITCH-mod_sofia/1.0.pre3-7870 Accept: application/sdp Accept-Encoding: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, REGISTER, INFO Supported: 100rel, precondition, timer Content-Length: 0 *Mar 13 14:40:10.431: HandleUdpSocketReads :Msg enqueued for SPI with IPaddr: 89.18.32.19:5080 *Mar 13 14:40:10.431: ccsip_spi_process_event:Could not find ccb for response