sh log Syslog logging: enabled (11 messages dropped, 87 messages rate-limited, 231 flushes, 0 overruns, xml disabled, filtering disabled) No Active Message Discriminator. No Inactive Message Discriminator. Console logging: disabled Monitor logging: level debugging, 6890 messages logged, xml disabled, filtering disabled Buffer logging: level debugging, 3264 messages logged, xml disabled, filtering disabled Logging Exception size (4096 bytes) Count and timestamp logging messages: disabled Persistent logging: disabled No active filter modules. ESM: 0 messages dropped Trap logging: level informational, 1207 message lines logged --More--   Log Buffer (5000000 bytes): Apr 12 17:17:34.166: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAddContextToTable: Added context(0x46AEB520) with key=[342] to table Apr 12 17:17:34.166: //1300/000000000000/SIP/State/sipSPIChangeState: 0x46AEB520 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE) Apr 12 17:17:34.166: //1300/000000000000/SIP/Info/ccsip_call_setup_request: Before processing SETUP REQccb->pld.flags_ipip = 200 Apr 12 17:17:34.166: //1300/000000000000/SIP/Info/ccsip_call_setup_request: This is a TDM-IP call: callID= 1300, peer_callID = 1299 Apr 12 17:17:34.166: //1300/000000000000/SIP/Info/ccsip_call_setup_request: After processing SETUP REQccb->pld.flags_ipip = 200 Apr 12 17:17:34.166: //1300/2CD2364C8F64/SIP/Info/sipSPIGetOutboundHostAndDestHost: CCSIP: target_host : 10.230.78.4 target_port : 5060 Apr 12 17:17:34.166: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_SETUP Apr 12 17:17:34.166: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 2 Apr 12 17:17:34.166: //1300/2CD2364C8F64/SIP/Info/sipSPIUaddccCallIdToTable: Adding call id 514 to table Apr 12 17:17:34.166: //1300/2CD2364C8F64/SIP/Info/sipSPIGetCallConfig: preferred_codec set[0] type :No Codec bytes: 0 --More--  Apr 12 17:17:34.166: //1300/2CD2364C8F64/SIP/Info/sipSPICanSetFallbackFlag: Local Fallback is not active Apr 12 17:17:34.166: //1300/2CD2364C8F64/SIP/Info/sipSPIGetCallConfig: Not using Voice Class Codec Apr 12 17:17:34.166: //1300/2CD2364C8F64/SIP/Info/sipSPIGetModemConfig: From Config: Modem NSE payload = 100, Passthrough = 4, Modem relay = 0, Gw-Xid = 1 SPRT latency 200, SPRT Retries = 12, Dict Size = 1024 String Len = 32, Compress dir = 3 Apr 12 17:17:34.166: //1300/2CD2364C8F64/SIP/Info/sipSPIValidateAndCopyOutboundHost: CCSIP: copy target_host to outbound_host Apr 12 17:17:34.166: //1300/2CD2364C8F64/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 10.230.78.1 Apr 12 17:17:34.166: //-1/xxxxxxxxxxxx/SIP/Media/sipSPIReserveRtpPort: reserved port 17966 for stream 1 Apr 12 17:17:34.166: //-1/xxxxxxxxxxxx/SIP/Info/convert_codec_bytes_to_ptime: Values :Codec: g711ulaw codecbytes :160, ptime: 20 Apr 12 17:17:34.166: //1300/2CD2364C8F64/SIP/Info/sip_generate_sdp_xcaps_list: Modem Relay and T38 disabled. X-cap not needed Apr 12 17:17:34.166: //1300/2CD2364C8F64/SIP/Info/sipSPIOutgoingCallSDP: Creating recv-only stream for outbound call Apr 12 17:17:34.166: //1300/2CD2364C8F64/SIP/Media/sipSPIProcessRtpSessions: sipSPIProcessRtpSessions --More--  Apr 12 17:17:34.166: //1300/2CD2364C8F64/SIP/Media/sipSPIProcessRtpSessions: No active streams. Apr 12 17:17:34.170: //1300/2CD2364C8F64/SIP/Info/sipSPIValidateGtd: Signal Forward disabled Apr 12 17:17:34.170: //1300/2CD2364C8F64/SIP/Info/sipSPIAddMLPPServicesInfo: No MLP Info available on incoming leg Apr 12 17:17:34.170: //1300/2CD2364C8F64/SIP/Info/act_idle_continue_call_setup: Apr 12 17:17:34.170: //1300/2CD2364C8F64/SIP/Info/sipSPIRscmsmAvail: Value returned by check is = 0 Apr 12 17:17:34.170: //1300/2CD2364C8F64/SIP/Info/sipSPIUaddCcbToUACTable: ****Adding to UAC table. Apr 12 17:17:34.170: //1300/2CD2364C8F64/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x46AEB520 key=2CD2D274-7EB11DD-8F679863-CBD64BBD@10.230.78.1 Apr 12 17:17:34.170: //1300/2CD2364C8F64/SIP/Info/sipSPIUsetBillingProfile: sipCallId for billing records = 2CD2D274-7EB11DD-8F679863-CBD64BBD@10.230.78.1 Apr 12 17:17:34.170: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 10.230.78.4,Port 5060, Transport 1, SentBy Port 5060 Apr 12 17:17:34.170: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Clock Time Zone is utc, same as GMT: Using GMT Apr 12 17:17:34.170: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIgetRegistrarHost: registrar is not configured Apr 12 17:17:34.170: //1300/2CD2364C8F64/SIP/Event/sipSPICreateRpid: Received Octet3A=0x80 -> Setting ;screen=no ;privacy=off --More--  Apr 12 17:17:34.170: //1300/2CD2364C8F64/SIP/Info/sipSPISendInvite: Associated container=0x474AE8B8 to Invite Apr 12 17:17:34.170: //1300/2CD2364C8F64/SIP/Transport/sipSPISendInvite: Sending Invite to the transport layer Apr 12 17:17:34.170: //1300/2CD2364C8F64/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Global configuration, Switch Transport is FALSE Apr 12 17:17:34.170: //1300/2CD2364C8F64/SIP/Transport/sipSPITransportSendMessage: msg=0x45BF41AC, addr=10.230.78.4, port=5060, sentBy_port=0, is_req=1, transport=1, switch=0, callBack=0x413D06DC Apr 12 17:17:34.170: //1300/2CD2364C8F64/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Apr 12 17:17:34.170: //1300/2CD2364C8F64/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0 Apr 12 17:17:34.170: //1300/2CD2364C8F64/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x45BF41AC Apr 12 17:17:34.170: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x45BF41AC, addr=10.230.78.4, port=5060, connId=1 for UDP Apr 12 17:17:34.170: //1300/2CD2364C8F64/SIP/Info/sentInviteRequest: Sent Invite in state STATE_IDLE Apr 12 17:17:34.170: //-1/xxxxxxxxxxxx/SIP/Info/sentInviteRequest: Transaction active. Facilities will be queued. Apr 12 17:17:34.170: //1300/2CD2364C8F64/SIP/State/sipSPIChangeState: 0x46AEB520 : State change from (STATE_IDLE, SUBSTATE_NONE) to (STATE_SENT_INVITE, SUBSTATE_NONE) --More--  Apr 12 17:17:34.170: //1300/2CD2364C8F64/SIP/Media/sipSPIProcessRtpSessions: sipSPIProcessRtpSessions Apr 12 17:17:34.170: //1300/2CD2364C8F64/SIP/Media/sipSPIAddStream: Adding stream 1 of type voice+dtmf (callid 1300) to the VOIP RTP library Apr 12 17:17:34.170: //1300/2CD2364C8F64/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 10.230.78.1 Apr 12 17:17:34.170: //1300/2CD2364C8F64/SIP/Media/sipSPIUpdateRtcpSession: sipSPIUpdateRtcpSession for m-line 1 Apr 12 17:17:34.170: //1300/2CD2364C8F64/SIP/Media/sipSPIUpdateRtcpSession: rtcp_session info laddr = 10.230.78.1, lport = 17966, raddr = 0.0.0.0, rport=0, do_rtcp=FALSE src_callid = 1300, dest_callid = -1, stream type = voice+dtmf, stream direction = RECVONLY media_ip_addr = 0.0.0.0, vrf tableid = 0 Apr 12 17:17:34.170: //1300/2CD2364C8F64/SIP/Media/sipSPIUpdateRtcpSession: No rtp session, creating a new one Apr 12 17:17:34.174: //1300/2CD2364C8F64/SIP/State/sipSPIChangeStreamState: Stream (callid = 1300) State changed from (STREAM_ADDING) to (STREAM_ACTIVE) Apr 12 17:17:34.174: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Sent: INVITE sip:1700@10.230.78.4:5060 SIP/2.0 Via: SIP/2.0/UDP 10.230.78.1:5060;branch=z9hG4bK34B1B3E Remote-Party-ID: ;party=calling;screen=no;privacy=off --More--   From: ;tag=57F122C-80E To: Date: Sat, 12 Apr 2008 17:17:34 GMT Call-ID: 2CD2D274-7EB11DD-8F679863-CBD64BBD@10.230.78.1 Supported: 100rel,timer,resource-priority,replaces Min-SE: 1800 Cisco-Guid: 751973964-132846045-2405734499-3419818941 User-Agent: Cisco-SIPGateway/IOS-12.x Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER CSeq: 101 INVITE Max-Forwards: 70 Timestamp: 1208020654 Contact: Call-Info: ;method="NOTIFY;Event=telephone-event;Duration=2000" Diversion: ;privacy=off;reason=user-busy;counter=1;screen=no Expires: 180 Allow-Events: telephone-event Content-Type: application/sdp Content-Disposition: session;handling=required --More--   Content-Length: 237 v=0 o=CiscoSystemsSIP-GW-UserAgent 6737 6471 IN IP4 10.230.78.1 s=SIP Call c=IN IP4 10.230.78.1 t=0 0 m=audio 17966 RTP/AVP 0 100 c=IN IP4 10.230.78.1 a=rtpmap:0 PCMU/8000 a=rtpmap:100 X-NSE/8000 a=fmtp:100 192-194 a=ptime:20 Apr 12 17:17:34.178: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpSocketReads: Msg enqueued for SPI with IP addr: 10.230.78.4:32790 Apr 12 17:17:34.178: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Apr 12 17:17:34.178: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x00000000 Apr 12 17:17:34.178: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog --More--  Apr 12 17:17:34.178: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.230.78.1:5060;branch=z9hG4bK34B1B3E To: ;tag=cuedd639d20 From: ;tag=57F122C-80E Call-ID: 2CD2D274-7EB11DD-8F679863-CBD64BBD@10.230.78.1 CSeq: 101 INVITE Content-Length: 0 Timestamp: 1208020654 Contact: Apr 12 17:17:34.178: //1300/2CD2364C8F64/SIP/State/sipSPIChangeState: 0x46AEB520 : State change from (STATE_SENT_INVITE, SUBSTATE_NONE) to (STATE_RECD_PROCEEDING, SUBSTATE_PROCEEDING_PROCEEDING) Apr 12 17:17:34.190: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpSocketReads: Msg enqueued for SPI with IP addr: 10.230.78.4:32790 Apr 12 17:17:34.190: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Apr 12 17:17:34.190: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x00000000 --More--  Apr 12 17:17:34.190: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog Apr 12 17:17:34.194: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.230.78.1:5060;branch=z9hG4bK34B1B3E To: ;tag=cuedd639d20 From: ;tag=57F122C-80E Call-ID: 2CD2D274-7EB11DD-8F679863-CBD64BBD@10.230.78.1 CSeq: 101 INVITE Content-Length: 0 Contact: Apr 12 17:17:34.194: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentGTD: No GTD found in inbound container Apr 12 17:17:34.194: //1300/2CD2364C8F64/SIP/Info/sipSPIGetContentSDP: No SDP found in inbound container Apr 12 17:17:34.194: //1300/2CD2364C8F64/SIP/Error/sipSPIProcessCallInfoHeader: Call-Info header with for Unsolicited Notify Absent,Disabling Unsolicited Notifies Apr 12 17:17:34.194: //1300/2CD2364C8F64/SIP/Info/ccsip_api_call_alert: SDP Body either absent or ignored in 180 RINGING:- will wait for 200 OK to do negotiation. --More--  Apr 12 17:17:34.194: //-1/xxxxxxxxxxxx/SIP/Info/sipSPICreateRawMsg: No GTD passed. Apr 12 17:17:34.194: //1300/2CD2364C8F64/SIP/Info/HandleSIP1xxRinging: ccsip_api_call_alert returned: SIP_SUCCESS Apr 12 17:17:34.194: //1300/2CD2364C8F64/SIP/State/sipSPIChangeState: 0x46AEB520 : State change from (STATE_RECD_PROCEEDING, SUBSTATE_PROCEEDING_PROCEEDING) to (STATE_RECD_PROCEEDING, SUBSTATE_NONE) Apr 12 17:17:34.194: //1300/2CD2364C8F64/SIP/Info/HandleSIP1xxRinging: Transaction Complete. Lock on Facilities released. Apr 12 17:17:34.206: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpSocketReads: Msg enqueued for SPI with IP addr: 10.230.78.4:32790 Apr 12 17:17:34.206: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Apr 12 17:17:34.206: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x00000000 Apr 12 17:17:34.206: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog Apr 12 17:17:34.206: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.230.78.1:5060;branch=z9hG4bK34B1B3E To: ;tag=cuedd639d20 From: ;tag=57F122C-80E --More--   Call-ID: 2CD2D274-7EB11DD-8F679863-CBD64BBD@10.230.78.1 CSeq: 101 INVITE Content-Length: 176 Contact: Content-Type: application/sdp Call-Info: ;method="NOTIFY;Event=telephone-event;Duration=2000" Allow-Events: telephone-event v=0 o=CiscoSystemsSIP-Workflow-App-UserAgent 2175 2175 IN IP4 10.230.78.4 s=SIP Call c=IN IP4 10.230.78.4 t=0 0 m=audio 16898 RTP/AVP 0 a=rtpmap:0 pcmu/8000 a=ptime:20 Apr 12 17:17:34.206: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentGTD: No GTD found in inbound container Apr 12 17:17:34.206: //1300/2CD2364C8F64/SIP/Info/sipSPIhandle200OKInvite: Transaction active. Facilities will be queued. --More--  Apr 12 17:17:34.206: //1300/2CD2364C8F64/SIP/Info/sipSPIhandle200OKInvite: *** This ccb is the parent Apr 12 17:17:34.210: //1300/2CD2364C8F64/SIP/Info/sipSPIProcessCallInfoHeader: Callinfo parsed - Destination url = , duration = 2000 Apr 12 17:17:34.210: //1300/2CD2364C8F64/SIP/Info/sipSPICompareRespMediaInfo: No Comparsion needed as 18x response SDP is either absent or ignored Apr 12 17:17:34.210: //1300/2CD2364C8F64/SIP/Info/sipSPIDoMediaNegotiation: Number of m-lines = 1 Apr 12 17:17:34.210: //1300/2CD2364C8F64/SIP/Info/sipSPIDoAudioNegotiation: Codec (g711ulaw) Negotiation Successful on Static Payload for m-line 1 Apr 12 17:17:34.210: //1300/2CD2364C8F64/SIP/Info/sipSPIDoPtimeNegotiation: One ptime attribute found - value:20 Apr 12 17:17:34.210: //-1/xxxxxxxxxxxx/SIP/Info/convert_ptime_to_codec_bytes: Values :Codec: g711ulaw ptime :20, codecbytes: 160 Apr 12 17:17:34.210: //-1/xxxxxxxxxxxx/SIP/Info/convert_codec_bytes_to_ptime: Values :Codec: g711ulaw codecbytes :160, ptime: 20 Apr 12 17:17:34.210: //1300/2CD2364C8F64/SIP/Media/sipSPIDoPtimeNegotiation: Offered ptime:20, Negotiated ptime:20 Negotiated codec bytes: 160 for codec g711ulaw Apr 12 17:17:34.210: //1300/2CD2364C8F64/SIP/Info/sipSPIDoDTMFRelayNegotiation: m-line index 1 Apr 12 17:17:34.210: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAddContextToTable: Added context(0x46AFFD80) with key=[343] to table --More--  Apr 12 17:17:34.210: //0/000000000000/SIP/Info/ccsip_new_scb: Created new scb: 0x46AFFD80 with id: -1 Apr 12 17:17:34.210: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_edb: Created new edb(0x472DFC10) Apr 12 17:17:34.210: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIUpdateEDBEvent: EDB updated with Event Name: telephone-event Event ID: Apr 12 17:17:34.210: //0/000000000000/SIP/Info/ccsip_create_implicit_subscribe_dialog: Q'd EDB(0x472DFC10) on SCB(0x46AFFD80) Apr 12 17:17:34.210: //-1/xxxxxxxxxxxx/SIP/Info/sipSPICreateSubscribeKey: Generated Subscribe Key : 2CD2D274-7EB11DD-8F679863-CBD64BBD@10.230.78.157F122C-80E Apr 12 17:17:34.210: //0/000000000000/SIP/Info/sipSPIPutSCBInClientTable: Inserting SCB with key 2CD2D274-7EB11DD-8F679863-CBD64BBD@10.230.78.157F122C-80E into ClientTable Apr 12 17:17:34.210: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_create_implicit_subscribe_dialog: Changing from State: SUBSCRIBE_STATE_IDLE to state SUBSCRIBE_STATE_ACTIVE Apr 12 17:17:34.210: //-1/xxxxxxxxxxxx/SIP/Info/sip_sdp_get_modem_relay_cap_params: NSE payload from X-cap = 0 Apr 12 17:17:34.210: //1300/2CD2364C8F64/SIP/Info/sip_select_modem_relay_params: X-tmr not present in SDP. Disable modem relay Apr 12 17:17:34.210: //1300/2CD2364C8F64/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 Apr 12 17:17:34.210: //1300/2CD2364C8F64/SIP/Info/sipSPIDoAudioNegotiation: Codec negotiation successful for media line 1 --More--   payload_type=0, codec_bytes=160, codec=g711ulaw, dtmf_relay=sip-notify stream_type=voice-only (0), dest_ip_address=10.230.78.4, dest_port=16898 Apr 12 17:17:34.210: //1300/2CD2364C8F64/SIP/State/sipSPIChangeStreamState: Stream (callid = -1) State changed from (STREAM_DEAD) to (STREAM_ADDING) Apr 12 17:17:34.210: //1300/2CD2364C8F64/SIP/Media/sipSPIUpdCallWithSdpInfo: Preferred Codec : g711ulaw, bytes :160 Preferred DTMF relay : sip-notify Preferred NTE payload : 101 Early Media : No Delayed Media : No Bridge Done : No New Media : No DSP DNLD Reqd : No Apr 12 17:17:34.210: //1300/2CD2364C8F64/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 10.230.78.1 Apr 12 17:17:34.210: //1300/2CD2364C8F64/SIP/Media/sipSPIUpdCallWithSdpInfo: Stream type : voice-only Media line : 1 State : STREAM_ADDING (2) Callid : 1300 Negotiated Codec : g711ulaw, bytes :160 Nego. Codec payload : 0 (tx), 0 (rx) --More--   Negotiated DTMF relay : sip-notify Negotiated NTE payload : 0 (tx), 0 (rx) Negotiated CN payload : 0 Media Srce Addr/Port : 10.230.78.1:17966 Media Dest Addr/Port : 10.230.78.4:16898 Apr 12 17:17:34.210: //1300/2CD2364C8F64/SIP/Info/sipSPIProcessMediaChanges: sipSPIProcessMediaChanges Apr 12 17:17:34.210: //1300/2CD2364C8F64/SIP/Info/sipSPIhandle200OKInvite: ccsip_api_call_connect_media returned: SIP_SUCCESS Apr 12 17:17:34.210: //1300/2CD2364C8F64/SIP/State/sipSPIChangeState: 0x46AEB520 : State change from (STATE_RECD_PROCEEDING, SUBSTATE_NONE) to (STATE_RECD_PROCEEDING, SUBSTATE_NONE) Apr 12 17:17:34.210: //-1/xxxxxxxxxxxx/SIP/Info/sipSPICreateRawMsg: No GTD passed. Apr 12 17:17:34.210: //1300/2CD2364C8F64/SIP/Info/sipSPIhandle200OKInvite: ccsip_api_call_connected returned: SIP_SUCCESS Apr 12 17:17:34.210: //1300/2CD2364C8F64/SIP/Transport/sipSPISendAck: Sending ACK to the transport layer Apr 12 17:17:34.210: //1300/2CD2364C8F64/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Global configuration, Switch Transport is FALSE Apr 12 17:17:34.210: //1300/2CD2364C8F64/SIP/Transport/sipSPITransportSendMessage: msg=0x45BF41AC, addr=10.230.78.4, port=5060, sentBy_port=0, is_req=1, transport=1, switch=0, callBack=0x413D1AC8 --More--  Apr 12 17:17:34.210: //1300/2CD2364C8F64/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Apr 12 17:17:34.210: //1300/2CD2364C8F64/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0 Apr 12 17:17:34.210: //1300/2CD2364C8F64/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x45BF41AC Apr 12 17:17:34.210: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x45BF41AC, addr=10.230.78.4, port=5060, connId=1 for UDP Apr 12 17:17:34.210: //1300/2CD2364C8F64/SIP/State/sipSPIChangeState: 0x46AEB520 : State change from (STATE_RECD_PROCEEDING, SUBSTATE_NONE) to (STATE_ACTIVE, SUBSTATE_NONE) Apr 12 17:17:34.210: //1300/2CD2364C8F64/SIP/Call/sipSPICallInfo: The Call Setup Information is: Call Control Block (CCB) : 0x46AEB520 State of The Call : STATE_ACTIVE TCP Sockets Used : NO Calling Number : 000447887895221 Called Number : 1700 Source IP Address (Sig ): 10.230.78.1 Destn SIP Req Addr:Port : 10.230.78.4:5060 Destn SIP Resp Addr:Port : 10.230.78.4:5060 Destination Name : 10.230.78.4 --More--  Apr 12 17:17:34.210: //1300/2CD2364C8F64/SIP/Call/sipSPIMediaCallInfo: Number of Media Streams: 1 Media Stream : 1 Negotiated Codec : g711ulaw Negotiated Codec Bytes : 160 Nego. Codec payload : 0 (tx), 0 (rx) Negotiated Dtmf-relay : 8 Dtmf-relay Payload : 0 (tx), 0 (rx) Source IP Address (Media): 10.230.78.1 Source IP Port (Media): 17966 Destn IP Address (Media): 10.230.78.4 Destn IP Port (Media): 16898 Orig Destn IP Address:Port (Media): 0.0.0.0:0 Apr 12 17:17:34.214: //1300/2CD2364C8F64/SIP/Info/sipSPICallActive: Transaction Complete. Lock on Facilities released. Apr 12 17:17:34.214: //1300/2CD2364C8F64/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd Apr 12 17:17:34.214: //1300/2CD2364C8F64/SIP/Info/ccsip_bridge: confID = 429, srcCallID = 1300, dstCallID = 1299 Apr 12 17:17:34.214: //1300/2CD2364C8F64/SIP/Info/sipSPIUupdateCcCallIds: Old src/dest ccCallids: -1/-1, new src/dest ccCallids: 1300/1299 Apr 12 17:17:34.214: //1300/2CD2364C8F64/SIP/Info/sipSPIUupdateCcCallIds: Old streamcallid=1300, new streamcallid=1300 --More--  Apr 12 17:17:34.214: //1300/2CD2364C8F64/SIP/Info/ccsip_bridge: xcoder_attached = 0, xmitFunc = 1097497448, ccb xmitFunc = 1097497448 Apr 12 17:17:34.214: //1300/2CD2364C8F64/SIP/Media/sipSPIProcessRtpSessions: sipSPIProcessRtpSessions Apr 12 17:17:34.214: //1300/2CD2364C8F64/SIP/Media/sipSPIAddStream: Adding stream 1 of type voice-only (callid 1300) to the VOIP RTP library Apr 12 17:17:34.214: //1300/2CD2364C8F64/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 10.230.78.1 Apr 12 17:17:34.214: //1300/2CD2364C8F64/SIP/Media/sipSPIUpdateRtcpSession: sipSPIUpdateRtcpSession for m-line 1 Apr 12 17:17:34.214: //1300/2CD2364C8F64/SIP/Media/sipSPIUpdateRtcpSession: rtcp_session info laddr = 10.230.78.1, lport = 17966, raddr = 10.230.78.4, rport=16898, do_rtcp=TRUE src_callid = 1300, dest_callid = 1299, stream type = voice-only, stream direction = SENDRECV media_ip_addr = 10.230.78.4, vrf tableid = 0 Apr 12 17:17:34.214: //1300/2CD2364C8F64/SIP/Media/sipSPIUpdateRtcpSession: RTP session already created - update Apr 12 17:17:34.214: //1300/2CD2364C8F64/SIP/Info/sipSPICreateAndStartRtpTimer: Apr 12 17:17:34.214: //1300/2CD2364C8F64/SIP/Info/sipSPICreateAndStartRtpTimer: Media Inactivity Timer is disabled. Apr 12 17:17:34.214: //1300/2CD2364C8F64/SIP/Media/sipSPIGetNewLocalMediaDirection: --More--   New Remote Media Direction = SENDRECV Present Local Media Direction = SENDRECV New Local Media Direction = SENDRECV retVal = 0 Apr 12 17:17:34.214: //1300/2CD2364C8F64/SIP/State/sipSPIChangeStreamState: Stream (callid = 1300) State changed from (STREAM_ADDING) to (STREAM_ACTIVE) Apr 12 17:17:34.214: //1300/2CD2364C8F64/SIP/Info/ccsip_get_rtcp_session_parameters: CURRENT VALUES: stream_callid=1300, current_seq_num=0xCD0 Apr 12 17:17:34.214: //1300/2CD2364C8F64/SIP/Info/ccsip_get_rtcp_session_parameters: NEW VALUES: stream_callid=1300, current_seq_num=0xD31 Apr 12 17:17:34.214: //1300/2CD2364C8F64/SIP/Info/ccsip_caps_ind: Load DSP with negotiated codec: g711ulaw, Bytes=160 Apr 12 17:17:34.214: //1300/2CD2364C8F64/SIP/Info/ccsip_caps_ind: Set forking flag to 0x0 Apr 12 17:17:34.214: //1300/2CD2364C8F64/SIP/Info/sipSPISetDTMFRelayMode: Set DSP for dtmf-relay = CC_CAP_DTMF_RELAY_OUT_OF_BAND Apr 12 17:17:34.214: //1300/2CD2364C8F64/SIP/Info/sip_set_modem_caps: Preferred (or the one that came from DSM) modem relay=1, from CLI config=0 Apr 12 17:17:34.214: //1300/2CD2364C8F64/SIP/Info/sip_set_modem_caps: Disabling Modem Relay... Apr 12 17:17:34.214: //1300/2CD2364C8F64/SIP/Info/sip_set_modem_caps: Negotiation already Done. Set negotiated Modem caps and generate SDP Xcap list --More--  Apr 12 17:17:34.214: //1300/2CD2364C8F64/SIP/Info/sip_set_modem_caps: Modem Relay & Passthru both disabled Apr 12 17:17:34.214: //1300/2CD2364C8F64/SIP/Info/sip_set_modem_caps: nse payload = 0, ptru mode = 0, ptru-codec=2, redundancy=0, xid=0, relay=0, sprt-retry=12, latecncy=200, compres-dir=3, dict=1024, strnlen=32 Apr 12 17:17:34.214: //1300/2CD2364C8F64/SIP/Media/sipSPISetStreamInfo: 1 Active Streams Apr 12 17:17:34.214: //1300/2CD2364C8F64/SIP/Media/sipSPISetStreamInfo: Adding stream type (voice-only) from media line 1 Apr 12 17:17:34.214: //1300/2CD2364C8F64/SIP/Media/sipSPISetStreamInfo: caps.stream_count=1,caps.stream[0].stream_type=0x1, caps.stream_list.xmitFunc= Apr 12 17:17:34.214: //1300/2CD2364C8F64/SIP/Media/sipSPISetStreamInfo: voip_rtp_xmit, caps.stream_list.context= Apr 12 17:17:34.214: //1300/2CD2364C8F64/SIP/Media/sipSPISetStreamInfo: 0x48A0CF20 (gccb) Apr 12 17:17:34.214: //1300/2CD2364C8F64/SIP/Info/ccsip_caps_ind: Load DSP with codec : g711ulaw, Bytes=160, payload = 0 Apr 12 17:17:34.214: //1300/2CD2364C8F64/SIP/Info/ccsip_caps_ind: ccsip_caps_ind: ccb->pld.flags_ipip = 0x201 Apr 12 17:17:34.218: //1300/2CD2364C8F64/SIP/Info/ccsip_caps_ack: Set forking flag to 0x7 Apr 12 17:17:34.218: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Sent: --More--  ACK sip:1700@10.230.78.4:5060 SIP/2.0 Via: SIP/2.0/UDP 10.230.78.1:5060;branch=z9hG4bK34C638 From: ;tag=57F122C-80E To: ;tag=cuedd639d20 Date: Sat, 12 Apr 2008 17:17:34 GMT Call-ID: 2CD2D274-7EB11DD-8F679863-CBD64BBD@10.230.78.1 Max-Forwards: 70 CSeq: 101 ACK Allow-Events: telephone-event Content-Length: 0 Apr 12 17:17:34.234: %ISDN-6-CONNECT: Interface Serial0/2/0:0 is now connected to 00447887895221 N/A Apr 12 17:17:40.234: %ISDN-6-CONNECT: Interface Serial0/2/0:0 is now connected to 00447887895221 N/A Apr 12 17:17:41.402: %ISDN-6-DISCONNECT: Interface Serial0/2/0:0 disconnected from 00447887895221 , call lasted 7 seconds Apr 12 17:17:41.406: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_DISCONNECT Apr 12 17:17:41.406: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 7 --More--  Apr 12 17:17:41.406: //1300/2CD2364C8F64/SIP/Info/sipSPIValidateGtd: Signal Forward disabled Apr 12 17:17:41.406: //1300/2CD2364C8F64/SIP/Info/preprocessDisconnect: No GTD in Rawmsg Apr 12 17:17:41.406: //1300/2CD2364C8F64/SIP/Info/sipSPIStopHoldTimer: Stopping hold timer Apr 12 17:17:41.406: //1300/2CD2364C8F64/SIP/Info/sipSPIStopHoldTimer: Stopping hold timer Apr 12 17:17:41.406: //1300/2CD2364C8F64/SIP/Info/sipSPISendBye: Associated container=0x45E6041C to Bye Apr 12 17:17:41.406: //1300/2CD2364C8F64/SIP/Transport/sipSPISendBye: Sending BYE to the transport layer Apr 12 17:17:41.406: //1300/2CD2364C8F64/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Global configuration, Switch Transport is FALSE Apr 12 17:17:41.406: //1300/2CD2364C8F64/SIP/Transport/sipSPITransportSendMessage: msg=0x45BF41AC, addr=10.230.78.4, port=5060, sentBy_port=0, is_req=1, transport=1, switch=0, callBack=0x413D14CC Apr 12 17:17:41.406: //1300/2CD2364C8F64/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately Apr 12 17:17:41.406: //1300/2CD2364C8F64/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0 Apr 12 17:17:41.406: //1300/2CD2364C8F64/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x45BF41AC --More--  Apr 12 17:17:41.406: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x45BF41AC, addr=10.230.78.4, port=5060, connId=1 for UDP Apr 12 17:17:41.406: //1300/2CD2364C8F64/SIP/Info/sentByeDisconnecting: Sent Bye Request, starting DisconnectTimer Apr 12 17:17:41.406: //1300/2CD2364C8F64/SIP/State/sipSPIChangeState: 0x46AEB520 : State change from (STATE_ACTIVE, SUBSTATE_NONE) to (STATE_DISCONNECTING, SUBSTATE_NONE) Apr 12 17:17:41.406: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Sent: BYE sip:1700@10.230.78.4:5060 SIP/2.0 Via: SIP/2.0/UDP 10.230.78.1:5060;branch=z9hG4bK34D68C From: ;tag=57F122C-80E To: ;tag=cuedd639d20 Date: Sat, 12 Apr 2008 17:17:34 GMT Call-ID: 2CD2D274-7EB11DD-8F679863-CBD64BBD@10.230.78.1 User-Agent: Cisco-SIPGateway/IOS-12.x Max-Forwards: 70 Timestamp: 1208020661 CSeq: 102 BYE Content-Length: 0 --More--  Apr 12 17:17:41.410: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpSocketReads: Msg enqueued for SPI with IP addr: 10.230.78.4:32790 Apr 12 17:17:41.410: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1 Apr 12 17:17:41.410: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x00000000 Apr 12 17:17:41.410: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog Apr 12 17:17:41.410: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.230.78.1:5060;branch=z9hG4bK34D68C To: ;tag=cuedd639d20 From: ;tag=57F122C-80E Call-ID: 2CD2D274-7EB11DD-8F679863-CBD64BBD@10.230.78.1 CSeq: 102 BYE Content-Length: 0 Apr 12 17:17:41.410: //1300/2CD2364C8F64/SIP/Info/sipSPIIcpifUpdate: CallState: 4 Playout: 4665 DiscTime:9222104 ConnTime 9221384 Apr 12 17:17:41.410: //1300/2CD2364C8F64/SIP/State/sipSPIChangeState: 0x46AEB520 : State change from (STATE_DISCONNECTING, SUBSTATE_NONE) to (STATE_DEAD, SUBSTATE_NONE) --More--  Apr 12 17:17:41.410: //1300/2CD2364C8F64/SIP/Call/sipSPICallInfo: The Call Setup Information is: Call Control Block (CCB) : 0x46AEB520 State of The Call : STATE_DEAD TCP Sockets Used : NO Calling Number : 000447887895221 Called Number : 1700 Source IP Address (Sig ): 10.230.78.1 Destn SIP Req Addr:Port : 10.230.78.4:5060 Destn SIP Resp Addr:Port : 10.230.78.4:5060 Destination Name : 10.230.78.4 Apr 12 17:17:41.410: //1300/2CD2364C8F64/SIP/Call/sipSPIMediaCallInfo: Number of Media Streams: 1 Media Stream : 1 Negotiated Codec : g711ulaw Negotiated Codec Bytes : 160 Nego. Codec payload : 0 (tx), 0 (rx) Negotiated Dtmf-relay : 8 Dtmf-relay Payload : 0 (tx), 0 (rx) Source IP Address (Media): 10.230.78.1 Source IP Port (Media): 17966 Destn IP Address (Media): 10.230.78.4 --More--  Destn IP Port (Media): 16898 Orig Destn IP Address:Port (Media): 0.0.0.0:0 Apr 12 17:17:41.410: //1300/2CD2364C8F64/SIP/Call/sipSPICallInfo: Disconnect Cause (CC) : 16 Disconnect Cause (SIP) : 200 Apr 12 17:17:41.410: //1300/2CD2364C8F64/SIP/Info/sipSPIUdeleteccCallIdFromTable: Removing call id 514 Apr 12 17:17:41.410: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDeleteContextFromTable: Context for key=[342] removed. Apr 12 17:17:41.410: //1300/2CD2364C8F64/SIP/Info/sipSPIUdeleteCcbFromUACTable: ****Deleting from UAC table. Apr 12 17:17:41.410: //1300/2CD2364C8F64/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x46AEB520 key=2CD2D274-7EB11DD-8F679863-CBD64BBD@10.230.78.1 Apr 12 17:17:41.414: //1300/2CD2364C8F64/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd Apr 12 17:17:41.414: //-1/xxxxxxxxxxxx/SIP/Event/ccsip_api_initiate_subscription_termination: Queued event from SIP SPI : SIPSPI_EV_SUBSCRIPTION_TERMINATED Apr 12 17:17:41.414: //-1/xxxxxxxxxxxx/SIP/Event/ccsip_api_initiate_subscription_termination: Queued event from SIP SPI : SIPSPI_EV_SUBSCRIPTION_TERMINATED Apr 12 17:17:41.414: //1300/2CD2364C8F64/SIP/Info/sipSPIUfreeOneCCB: Freeing ccb 46AEB520 --More--  Apr 12 17:17:41.414: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContextFromTable: NO context for key[342] Apr 12 17:17:41.418: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 7 for event 210 Apr 12 17:17:41.418: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_spi_process_app_subscribe_event: Event [SIPSPI_EV_SUBSCRIPTION_TERMINATED] received in State [SUBSCRIBE_STATE_ACTIVE] Apr 12 17:17:41.418: //0/000000000000/SIP/Info/act_subscription_terminated: Resetting server EDB flag Apr 12 17:17:41.418: //0/000000000000/SIP/Info/sipSPITerminateEvent: 1 Events still active on this Subscription Dialog Apr 12 17:17:41.418: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 7 for event 210 Apr 12 17:17:41.418: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_spi_process_app_subscribe_event: Event [SIPSPI_EV_SUBSCRIPTION_TERMINATED] received in State [SUBSCRIBE_STATE_ACTIVE] Apr 12 17:17:41.418: //0/000000000000/SIP/Info/act_subscription_terminated: Resetting Client EDB flag Apr 12 17:17:41.418: //0/000000000000/SIP/Info/sipSPIFreeOneEDB: There are 1 EDBs on edbQ Apr 12 17:17:41.418: //0/000000000000/SIP/Info/sipSPIFreeOneEDB: DeQ'd EDB(0x472DFC10) Apr 12 17:17:41.418: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIFreeOneEDB: EnQing EDB(0x472DFC10) for reuse --More--  Apr 12 17:17:41.418: //0/000000000000/SIP/Info/sipSPITerminateEvent: Freeing SCB(0x46AFFD80), 0 active events present Apr 12 17:17:41.418: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDeleteContextFromTable: Context for key=[343] removed. Apr 12 17:17:41.418: //0/000000000000/SIP/Info/sipSPIRemoveSCBFromClientTable: Removing SCB(0x46AFFD80) with Key(2CD2D274-7EB11DD-8F679863-CBD64BBD@10.230.78.157F122C-80E) from Client Table Apr 12 17:17:41.418: //0/000000000000/SIP/Info/sipSPIFreeOneSCB: EnQing SCB(0x46AFFD80) for reuse ROBUCRTGS0001#