*Sep 21 18:27:04.543: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpSocketReads: Msg enqueued for SPI with IP addr: 65.72.32.5:5060 *Sep 21 18:27:04.543: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x00000000 *Sep 21 18:27:04.543: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: INVITE sip:6105559999@206.231.245.253 SIP/2.0 Via: SIP/2.0/UDP 65.72.32.5:5060;branch=z9hG4bK000005e100000001cea17a070000414820051f4a34983466739692 Via: SIP/2.0/UDP 206.161.122.7;branch=z9hG4bK-BroadWorks.206.161.122.7-65.72.32.5V8010-0-346673969-1638002938-1190399288929- Record-Route: From: ;tag=1638002938-1190399288929- To: "8123 User" Call-ID: BW1428089292109071866666989@206.161.122.7 CSeq: 346673969 INVITE Contact: supported: 100rel max-forwards: 10 Allow: ACK, BYE, CANCEL, INFO, INVITE, OPTIONS, PRACK, REFER, UPDATE, NOTIFY Content-Type: application/sdp Accept: multipart/mixed, application/sdp Content-Length: 00234 v=0 o=BroadWorks 45108210 1 IN IP4 65.72.32.5 s=- c=IN IP4 65.72.32.5 t=0 0 m=audio 36912 RTP/AVP 0 8 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 *Sep 21 18:27:04.543: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 65.72.32.5,Port 5060, Transport 1, SentBy Port 5060 *Sep 21 18:27:04.543: //-1/164A2EC08230/SIP/State/sipSPIChangeState: 0x44E4A210 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE) *Sep 21 18:27:04.543: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 65.72.32.5,Port 5060, Transport 1, SentBy Port 5060 *Sep 21 18:27:04.543: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Clock Time Zone is UTC, same as GMT: Using GMT *Sep 21 18:27:04.547: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 65.72.32.5,Port 5060, Transport 1, SentBy Port 5060 *Sep 21 18:27:04.547: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetGtdBody: No valid GTD body found. *Sep 21 18:27:04.547: //-1/164A2EC08230/SIP/Info/sipSPIUaddCcbToUASReqTable: ****Adding to UAS Request table. *Sep 21 18:27:04.547: //-1/164A2EC08230/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x44E4A210 key=BW1428089292109071866666989@206.161.122.76105559999 *Sep 21 18:27:04.547: //-1/164A2EC08230/SIP/Info/ccsip_apply_sip_to_pstn_calling_policy: Override calling name *Sep 21 18:27:04.547: //-1/164A2EC08230/SIP/Info/sipSPIMatchSrcIpGroup: Match not found on carrier id *Sep 21 18:27:04.547: //-1/164A2EC08230/SIP/Info/sipSPIMatchSrcIpGroup: Match not found on Incoming called number: 6105559999 *Sep 21 18:27:04.547: //-1/164A2EC08230/SIP/Info/sipSPIMatchSrcIpGroup: Match not found on destination pattern: *Sep 21 18:27:04.547: //-1/164A2EC08230/SIP/Info/ccsipUpdateIncomingCallParams: ccCallInfo: Calling name 6104365293@ctdi.com, number , Calling oct3 0x00, oct_3a 0x00, Called number 6105559999 *Sep 21 18:27:04.547: //-1/164A2EC08230/SIP/Info/sipSPIGetCallConfig: Peer tag 7 matched for incoming call *Sep 21 18:27:04.547: //-1/164A2EC08230/SIP/Info/sipSPIGetCallConfig: Using Voice Class Codec, tag = 99 *Sep 21 18:27:04.547: //-1/164A2EC08230/SIP/Info/sipSPIContinueNewMsgInvite: Calling name , number , Calling oct3 0x00, oct_3a 0x80, ext_priv 0x00, Called number 6105559999, oct3 0x00 *Sep 21 18:27:04.547: //-1/164A2EC08230/SIP/Info/sipSPIContinueNewMsgInvite: Carrier id code , prev_cid NONE, next_cid NONE, prev_tgrp NONE, next_tgrp NONE *Sep 21 18:27:04.547: //-1/164A2EC08230/SIP/Info/sipSPIContinueNewMsgInvite: Requires reliable-provisional support *Sep 21 18:27:04.547: //-1/164A2EC08230/SIP/Info/sipSPIRscmsmAvail: Value returned by check is = 0 *Sep 21 18:27:04.547: //397/164A2EC08230/SIP/Info/sipSPIDoMediaNegotiation: Number of m-lines = 1 *Sep 21 18:27:04.547: //397/164A2EC08230/SIP/Info/sipSPIDoAudioNegotiation: Codec (g711ulaw) Negotiation Successful on Static Payload for m-line 1 *Sep 21 18:27:04.547: //397/164A2EC08230/SIP/Info/sipSPIDoPtimeNegotiation: No ptime present or multiple ptime attributes that can't be handled *Sep 21 18:27:04.547: //397/164A2EC08230/SIP/Info/sipSPIDoDTMFRelayNegotiation: m-line index 1 *Sep 21 18:27:04.547: //397/164A2EC08230/SIP/Info/sipSPICheckDynPayloadUse: Dynamic payload(101) could not be reserved. *Sep 21 18:27:04.547: //397/164A2EC08230/SIP/Info/sipSPIDoDTMFRelayNegotiation: Payload type (101) is reserved for requested dtmf relay mode. *Sep 21 18:27:04.551: //397/164A2EC08230/SIP/Info/sipSPIDoDTMFRelayNegotiation: Case of partial named event(NE) match in fmtp list of events. *Sep 21 18:27:04.551: //-1/xxxxxxxxxxxx/SIP/Info/sip_sdp_get_modem_relay_cap_params: NSE payload from X-cap = 0 *Sep 21 18:27:04.551: //397/164A2EC08230/SIP/Info/sip_select_modem_relay_params: X-tmr not present in SDP. Disable modem relay *Sep 21 18:27:04.551: //397/164A2EC08230/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 *Sep 21 18:27:04.551: //397/164A2EC08230/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=65.72.32.5, dest_port=36912 *Sep 21 18:27:04.551: //397/164A2EC08230/SIP/Media/sipSPIUpdCallWithSdpInfo: Preferred Codec : g729r8, bytes :20 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 *Sep 21 18:27:04.551: //397/164A2EC08230/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 206.231.245.253 *Sep 21 18:27:04.551: //397/164A2EC08230/SIP/Info/sipSPI_ipip_report_media_to_peer: callId 397 peer 0 flags 0x201 *Sep 21 18:27:04.551: //397/164A2EC08230/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: CallID 397, sdp 0x463B2E78 channels 0x44E4BDC0 *Sep 21 18:27:04.551: //397/164A2EC08230/SIP/Info/copy_channels: callId 397 size 0 ptr 0x45072CD8) SIP: (397) Attribute ptime, level 1 instance 1 not found. *Sep 21 18:27:04.551: //397/164A2EC08230/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: Hndl ptype 0 mline 1 *Sep 21 18:27:04.551: //397/164A2EC08230/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: Selecting codec g711ulaw *Sep 21 18:27:04.551: //-1/xxxxxxxxxxxx/SIP/Info/convert_codec_bytes_to_ptime: Values :Codec: g711ulaw codecbytes :160, ptime: 20 *Sep 21 18:27:04.551: //397/164A2EC08230/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: Media negotiation done: stream->negotiated_ptime=0,stream->negotiated_codec_bytes=160, coverted ptime=20 stream->mline_index=1, media_ndx=1 *Sep 21 18:27:04.551: //397/164A2EC08230/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: Adding codec 5 ptype 0 time 20, bytes 160 as channel 0 mline 1 ss 0 65.72.32.5:36912 *Sep 21 18:27:04.551: //397/164A2EC08230/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: Hndl ptype 8 mline 1 *Sep 21 18:27:04.551: //397/164A2EC08230/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: Selecting codec g711alaw SIP: (397) Attribute ptime, level 1 instance 1 not found. *Sep 21 18:27:04.551: //397/164A2EC08230/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: Media negotiation NOT done, get ptime from sdp: ptime=0, media_ndx=1 *Sep 21 18:27:04.551: //-1/xxxxxxxxxxxx/SIP/Info/convert_ptime_to_codec_bytes: Values :Codec: g711alaw ptime :0, codecbytes: 0 *Sep 21 18:27:04.551: //397/164A2EC08230/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: Codec bytes 0, use default packet rate 160 *Sep 21 18:27:04.551: //397/164A2EC08230/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: Adding codec 6 ptype 8 time 0, bytes 160 as channel 1 mline 1 ss 0 65.72.32.5:36912 *Sep 21 18:27:04.551: //397/164A2EC08230/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: Hndl ptype 18 mline 1 *Sep 21 18:27:04.551: //397/164A2EC08230/SIP/Media/sipSPISelectCodecVersion: g729br8 flavor of g729 codec will be used *Sep 21 18:27:04.551: //397/164A2EC08230/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: Selecting codec g729br8 SIP: (397) Attribute ptime, level 1 instance 1 not found. *Sep 21 18:27:04.551: //397/164A2EC08230/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: Media negotiation NOT done, get ptime from sdp: ptime=0, media_ndx=1 *Sep 21 18:27:04.555: //-1/xxxxxxxxxxxx/SIP/Info/convert_ptime_to_codec_bytes: Values :Codec: g729br8 ptime :0, codecbytes: 0 *Sep 21 18:27:04.555: //397/164A2EC08230/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: Codec bytes 0, use default packet rate 20 *Sep 21 18:27:04.555: //397/164A2EC08230/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: Adding codec 12 ptype 18 time 0, bytes 20 as channel 2 mline 1 ss 0 65.72.32.5:36912 *Sep 21 18:27:04.555: //397/164A2EC08230/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: Hndl ptype 101 mline 1 *Sep 21 18:27:04.555: //397/164A2EC08230/SIP/Info/sipSPI_ipip_report_media_to_peer: Report initial call media *Sep 21 18:27:04.555: //397/164A2EC08230/SIP/Info/copy_channels: callId 397 size 224 ptr 0x46E66664) *Sep 21 18:27:04.555: //397/164A2EC08230/SIP/Info/sipSPI_ipip_report_media_to_peer: CCSIP: Unable to report channel ind *Sep 21 18:27:04.555: //397/xxxxxxxxxxxx/CCAPI/cc_api_caps_ind: Call Entry Is Not Found *Sep 21 18:27:04.555: //397/164A2EC08230/SIP/Media/sipSPIUpdCallWithSdpInfo: Stream type : voice+dtmf Media line : 1 State : STREAM_ADDING (2) Callid : -1 Negotiated Codec : g711ulaw, bytes :160 Negotiated DTMF relay : rtp-nte Negotiated NTE payload : 101 Negotiated CN payload : 0 Media Srce Addr/Port : 206.231.245.253:0 Media Dest Addr/Port : 65.72.32.5:36912 *Sep 21 18:27:04.555: //397/164A2EC08230/SIP/Info/sipSPIHandleInviteMedia: Negotiated Codec : g711ulaw, bytes :160 Preferred Codec : g729r8, bytes :20 Preferred DTMF relay 1 : 6 Preferred DTMF relay 2 : 0 Negotiated DTMF relay : 6 Preferred and Negotiated NTE payloads: 101 101 Preferred and Negotiated NSE payloads: 100 0 Preferred and Negotiated Modem Relay: 0 0 Preferred and Negotiated Modem Relay GwXid: 1 0 *Sep 21 18:27:04.555: //397/164A2EC08230/SIP/Info/sipSPIDoQoSNegotiation: SDP body with media description *Sep 21 18:27:04.555: //397/164A2EC08230/SIP/Info/sipSPICanSetFallbackFlag: Local Fallback is not active *Sep 21 18:27:04.555: //-1/xxxxxxxxxxxx/SIP/Media/sipbug CCAPI: debug voip ccapi inout is ON (filter is OFF) CCSIP SPI: SIP Call Statistics tracing is enabled (filter is OFF) CCSIP SPI: SIP Call Message tracing is enabled (filter is OFF) CCSIP SPI: SIP Call State Machine tracing is enabled (filter is OFF) CCSIP SPI: SIP Call Events tracing is enabled (filter is OFF) CCSIP SPI: SIP error debug tracing is enabled (filter is OFF) CCSIP SPI: SIP info debug tracing is enabled (filter is OFF) CCSIP SPI: SIP media debug tracing is enabled (filter is OFF) CCSIP SPI: SIP Call preauth tracing is enabled (filter is OFF) CCSIP SPI: SIP Call transport tracing is enabled (filter is OFF) HQ-WAN-MAIN#SPIReserveRtpPort: reserved port 18866 for stream 1 *Sep 21 18:27:04.555: //397/164A2EC08230/SIP/Info/sipSPIUpdateSrcSdpFixedPart: Reserving rtp port for stream 1, src_port=18866 *Sep 21 18:27:04.555: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetMediaDirectionForStream: Setting Media direction SENDRECV for stream 1 *Sep 21 18:27:04.555: //397/164A2EC08230/SIP/Info/sipSPIUpdateSrcSdpVariablePart: Setting stream 1 portnum to 18866 *Sep 21 18:27:04.555: //397/164A2EC08230/SIP/Info/sipSPIUpdateSrcSdpVariablePart: Negotiated method of dtmf relayand pyld: 6 101 *Sep 21 18:27:04.555: //397/164A2EC08230/SIP/Info/sipSPIAddBillingInfoToCcb: sipCallId for billing records = BW1428089292109071866666989@206.161.122.7 *Sep 21 18:27:04.555: //397/164A2EC08230/SIP/Info/sipSPI_ipip_store_channel_info: Store channelInfo in CallInfo *Sep 21 18:27:04.555: //-1/xxxxxxxxxxxx/SIP/Info/sipSPICreateRawMsg: No GTD passed. *Sep 21 18:27:04.555: //-1/164A2EC08230/CCAPI/cc_api_display_ie_subfields: cc_api_call_setup_ind_common: cisco-username= ----- ccCallInfo IE subfields ----- cisco-ani= cisco-anitype=0 cisco-aniplan=0 cisco-anipi=0 cisco-anisi=0 dest=6105559999 cisco-desttype=0 cisco-destplan=0 cisco-rdie=FFFFFFFF cisco-rdn= cisco-rdntype=0 cisco-rdnplan=0 cisco-rdnpi=0 cisco-rdnsi=0 cisco-redirectreason=-1 *Sep 21 18:27:04.555: //-1/164A2EC08230/CCAPI/cc_api_call_setup_ind_common: Interface=0x45DB0890, Call Info( Calling Number=(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed), Called Number=6105559999(TON=Unknown, NPI=Unknown), Calling Translated=FALSE, Subscriber Type Str=Unknown, FinalDestinationFlag=TRUE, Incoming Dial-peer=7, Progress Indication=NULL(0), Calling IE Present=FALSE, Source Trkgrp Route Label=, Target Trkgrp Route Label=, CLID Transparent=FALSE), Call Id=397 *Sep 21 18:27:04.559: //-1/164A2EC08230/CCAPI/ccCheckClipClir: In: Calling Number=6105559999(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed) *Sep 21 18:27:04.559: //-1/164A2EC08230/CCAPI/ccCheckClipClir: Out: Calling Number=6105559999(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed) *Sep 21 18:27:04.559: //397/164A2EC08230/CCAPI/cc_api_call_setup_ind_common: Set Up Event Sent; Call Info(Calling Number=6105559999(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed), Called Number=6105559999(TON=Unknown, NPI=Unknown)) *Sep 21 18:27:04.559: //397/164A2EC08230/SIP/Info/sipSPIContinueNewMsgInvite: ccsip_api_call_setup_ind returned: SIP_SUCCESS *Sep 21 18:27:04.559: //397/164A2EC08230/SIP/Info/sipSPIUaddCcbToUASRespTable: ****Adding to UAS Response table. *Sep 21 18:27:04.559: //397/164A2EC08230/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x44E4A210 key=BW1428089292109071866666989@206.161.122.711F54038-1CC4 *Sep 21 18:27:04.559: //397/164A2EC08230/SIP/Info/sipSPIUaddccCallIdToTable: Adding call id 18D to table *Sep 21 18:27:04.559: //397/164A2EC08230/SIP/Transport/sipSPITransportSendMessage: msg=0x45A62C54, addr=65.72.32.5, port=5060, sentBy_port=5060, is_req=0, transport=1, switch=0, callBack=0x00000000 *Sep 21 18:27:04.559: //397/164A2EC08230/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately *Sep 21 18:27:04.559: //397/164A2EC08230/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0 *Sep 21 18:27:04.559: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x45A62C54, addr=65.72.32.5, port=5060, connId=0 for UDP *Sep 21 18:27:04.559: //397/164A2EC08230/SIP/State/sipSPIChangeState: 0x44E4A210 : State change from (STATE_IDLE, SUBSTATE_NONE) to (STATE_RECD_INVITE, SUBSTATE_NONE) *Sep 21 18:27:04.559: //397/164A2EC08230/SIP/Info/sipSPIProcessContactInfo: Previous Hop 65.72.32.5:5060 *Sep 21 18:27:04.559: //397/164A2EC08230/CCAPI/cc_process_call_setup_ind: Event=0x46CD6FC0 *Sep 21 18:27:04.563: //397/164A2EC08230/CCAPI/ccCallSetContext: Context=0x46E4287C *Sep 21 18:27:04.563: //397/164A2EC08230/CCAPI/cc_process_call_setup_ind: >>>>CCAPI handed cid 397 with tag 7 to app "_ManagedAppProcess_Default" *Sep 21 18:27:04.567: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Sent: SIP/2.0 100 Trying Via: SIP/2.0/UDP 65.72.32.5:5060;branch=z9hG4bK000005e100000001cea17a070000414820051f4a34983466739692,SIP/2.0/UDP 206.161.122.7;branch=z9hG4bK-BroadWorks.206.161.122.7-65.72.32.5V8010-0-346673969-1638002938-1190399288929- From: ;tag=1638002938-1190399288929- To: "8123 User" ;tag=11F54038-1CC4 Date: Fri, 21 Sep 2007 18:27:04 GMT Call-ID: BW1428089292109071866666989@206.161.122.7 Server: Cisco-SIPGateway/IOS-12.x CSeq: 346673969 INVITE Allow-Events: telephone-event Content-Length: 0 *Sep 21 18:27:04.567: //397/164A2EC08230/CCAPI/ccCallProceeding: Progress Indication=NULL(0) *Sep 21 18:27:04.567: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_PROCEEDING *Sep 21 18:27:04.571: //397/164A2EC08230/CCAPI/ccCallSetupRequest: Destination=, Calling IE Present=TRUE, Mode=0, Outgoing Dial-peer=1, Params=0x46E4A48C, Progress Indication=NULL(0) *Sep 21 18:27:04.571: //397/164A2EC08230/CCAPI/ccCheckClipClir: In: Calling Number=6105559999(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed) *Sep 21 18:27:04.571: //397/164A2EC08230/CCAPI/ccCheckClipClir: Out: Calling Number=6105559999(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed) *Sep 21 18:27:04.571: //397/164A2EC08230/CCAPI/ccCallSetupRequest: Destination Pattern=.T, Called Number=6105559999, Digit Strip=TRUE *Sep 21 18:27:04.571: //397/164A2EC08230/CCAPI/ccCallSetupRequest: Calling Number=6105559999(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed), Called Number=6105559999(TON=Unknown, NPI=Unknown), Redirect Number=, Display Info=6104365293@ctdi.com Account Number=, Final Destination Flag=TRUE, Guid=164A2EC0-67A7-11DC-8230-841B4392E3BF, Outgoing Dial-peer=1 *Sep 21 18:27:04.571: //397/164A2EC08230/CCAPI/cc_api_display_ie_subfields: ccCallSetupRequest: cisco-username= ----- ccCallInfo IE subfields ----- cisco-ani=6105559999 cisco-anitype=0 cisco-aniplan=0 cisco-anipi=0 cisco-anisi=0 dest=6105559999 cisco-desttype=0 cisco-destplan=0 cisco-rdie=FFFFFFFF cisco-rdn= cisco-rdntype=0 cisco-rdnplan=0 cisco-rdnpi=0 cisco-rdnsi=0 cisco-redirectreason=-1 *Sep 21 18:27:04.571: //397/164A2EC08230/CCAPI/ccIFCallSetupRequestPrivate: Interface=0x46C37078, Interface Type=6, Destination=, Mode=0x0, Call Params(Calling Number=6105559999(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed), Called Number=6105559999(TON=Unknown, NPI=Unknown), Calling Translated=FALSE, Subscriber Type Str=Unknown, FinalDestinationFlag=TRUE, Outgoing Dial-peer=1, Call Count On=FALSE, Source Trkgrp Route Label=, Target Trkgrp Route Label=, tg_label_flag=0, Application Call Id=) *Sep 21 18:27:04.571: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_event_handler: *Sep 21 18:27:04.571: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_event_handler: switch(ev.ev_id: 138) *Sep 21 18:27:04.571: //397/164A2EC08230/SIP/Info/ccsip_event_handler: ccsip_event_handler: peer ID 398 chans 0x46EC6988 event 138 flags 0x12020038 0x601 data 0x46EC6988 *Sep 21 18:27:04.571: //397/164A2EC08230/SIP/Info/ccsip_event_handler: ccsip_event_handler: CC_EV_H245_SET_MODE: peer ID 398 chans 0x46EC6988 event 138 flags 0x12020038 0x601 data 0x46EC6988 *Sep 21 18:27:04.571: //397/164A2EC08230/SIP/Info/ccsip_event_handler: ccsip_event_handler: CC_EV_H245_SET_MODE: peer ID 398 chans 0x46EC6988 event 138 flags 0x12020038 0x601 data 0x46EC6988, type = 6 *Sep 21 18:27:04.571: //397/164A2EC08230/SIP/Info/ccsip_event_handler: ccsip_event_handler: !!!!!CC_EV_H245_SET_MODE: not clearing VTSP flag *Sep 21 18:27:04.571: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_event_handler: CC_R_SUCCESS_WITH_CONFIRMED *Sep 21 18:27:04.571: //398/164A2EC08230/CCAPI/ccIFCallSetupRequestPrivate: SPI Call Setup Request Is Success; Interface Type=6, FlowMode=1 *Sep 21 18:27:04.575: //398/164A2EC08230/CCAPI/ccCallSetContext: Context=0x46E4A43C *Sep 21 18:27:04.575: //397/164A2EC08230/CCAPI/ccSaveDialpeerTag: Outgoing Dial-peer=1 *Sep 21 18:27:04.579: //398/164A2EC08230/CCAPI/cc_api_call_proceeding: Interface=0x46C37078, Progress Indication=NULL(0) *Sep 21 18:27:05.131: //398/164A2EC08230/CCAPI/cc_api_call_disconnected: Cause Value=44, Interface=0x46C37078, Call Id=398 *Sep 21 18:27:05.131: //398/164A2EC08230/CCAPI/cc_api_call_disconnected: Call Entry(Responsed=TRUE, Cause Value=44, Retry Count=0) *Sep 21 18:27:05.131: //398/164A2EC08230/CCAPI/ccCallSetAAA_Accounting: Accounting=0, Call Id=398 *Sep 21 18:27:05.131: //398/164A2EC08230/CCAPI/ccCallDisconnect: Cause Value=44, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=44) *Sep 21 18:27:05.131: //398/164A2EC08230/CCAPI/ccCallDisconnect: Cause Value=44, Call Entry(Responsed=TRUE, Cause Value=44) *Sep 21 18:27:05.531: //398/164A2EC08230/CCAPI/cc_api_call_feature: Feature Type=6, Interface=0x46C37078, Call Id=398 *Sep 21 18:27:05.535: //397/164A2EC08230/CCAPI/ccCallFeature: Feature Type=6, Call Id=397 *Sep 21 18:27:05.535: //-1/xxxxxxxxxxxx/SIP/Event/ccsip_call_feature: Ignoring non-hookflash feature event (0x00000006) *Sep 21 18:27:05.535: //398/164A2EC08230/CCAPI/cc_api_call_disconnect_done: Disposition=0, Interface=0x46C37078, Tag=0x0, Call Id=398, Call Entry(Disconnect Cause=44, Voice Class Cause Code=0, Retry Count=0) *Sep 21 18:27:05.535: //398/164A2EC08230/CCAPI/cc_api_call_disconnect_done: Call Disconnect Event Sent *Sep 21 18:27:05.539: //397/164A2EC08230/CCAPI/ccCallDisconnect: Cause Value=44, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=0) *Sep 21 18:27:05.539: //397/164A2EC08230/CCAPI/ccCallDisconnect: Cause Value=44, Call Entry(Responsed=TRUE, Cause Value=44) *Sep 21 18:27:05.539: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_DISCONNECT *Sep 21 18:27:05.539: //397/164A2EC08230/SIP/Info/act_recdinvite_disconnect: Performing disconnect *Sep 21 18:27:05.539: //397/164A2EC08230/SIP/Info/sipSPIValidateGtd: No rawMsg from CCAPI *Sep 21 18:27:05.539: //397/164A2EC08230/SIP/Transport/sipSPITransportSendMessage: msg=0x45A62BC4, addr=65.72.32.5, port=5060, sentBy_port=5060, is_req=0, transport=1, switch=0, callBack=0x4106008C *Sep 21 18:27:05.539: //397/164A2EC08230/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately *Sep 21 18:27:05.539: //397/164A2EC08230/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0 *Sep 21 18:27:05.539: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x45A62BC4, addr=65.72.32.5, port=5060, connId=0 for UDP *Sep 21 18:27:05.539: //397/164A2EC08230/SIP/Info/sentErrResDisconnecting: Sent an 3456XX Error Response *Sep 21 18:27:05.539: //397/164A2EC08230/SIP/State/sipSPIChangeState: 0x44E4A210 : State change from (STATE_RECD_INVITE, SUBSTATE_NONE) to (STATE_DISCONNECTING, SUBSTATE_NONE) *Sep 21 18:27:05.543: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Sent: SIP/2.0 500 Internal Server Error Via: SIP/2.0/UDP 65.72.32.5:5060;branch=z9hG4bK000005e100000001cea17a070000414820051f4a34983466739692,SIP/2.0/UDP 206.161.122.7;branch=z9hG4bK-BroadWorks.206.161.122.7-65.72.32.5V8010-0-346673969-1638002938-1190399288929- From: ;tag=1638002938-1190399288929- To: "8123 User" ;tag=11F54038-1CC4 Date: Fri, 21 Sep 2007 18:27:04 GMT Call-ID: BW1428089292109071866666989@206.161.122.7 Server: Cisco-SIPGateway/IOS-12.x CSeq: 346673969 INVITE Allow-Events: telephone-event Reason: Q.850;cause=44 Content-Length: 0 *Sep 21 18:27:05.571: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpSocketReads: Msg enqueued for SPI with IP addr: 65.72.32.5:5060 *Sep 21 18:27:05.571: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x00000000 *Sep 21 18:27:05.571: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Received: ACK sip:6105559999@206.231.245.253 SIP/2.0 Via: SIP/2.0/UDP 65.72.32.5:5060;branch=z9hG4bK000005e100000001cea17a070000414820051f4a34983466739692 Via: SIP/2.0/UDP 206.161.122.7;branch=z9hG4bK-BroadWorks.206.161.122.7-65.72.32.5V8010-0-346673969-1638002938-1190399288929- Record-Route: From: ;tag=1638002938-1190399288929- To: "8123 User" ;tag=11F54038-1CC4 Call-ID: BW1428089292109071866666989@206.161.122.7 CSeq: 346673969 ACK max-forwards: 10 Content-Length: 0 *Sep 21 18:27:05.575: //397/164A2EC08230/SIP/Info/sipSPIFindCcbUASReqTable: *****CCB found in UAS Request table. ccb=0x44E4A210 *Sep 21 18:27:05.575: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 65.72.32.5,Port 5060, Transport 1, SentBy Port 5060 *Sep 21 18:27:05.575: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Clock Time Zone is UTC, same as GMT: Using GMT *Sep 21 18:27:05.575: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Subsq Transaction Address 65.72.32.5,Port 5060, Transport 1, SentBy Port 5060 *Sep 21 18:27:05.575: //397/164A2EC08230/SIP/Info/sipSPIIcpifUpdate: CallState: 2 Playout: 0 DiscTime:30128646 ConnTime 0 *Sep 21 18:27:05.575: //397/164A2EC08230/CCAPI/cc_api_call_disconnect_done: Disposition=0, Interface=0x45DB0890, Tag=0x0, Call Id=397, Call Entry(Disconnect Cause=44, Voice Class Cause Code=0, Retry Count=0) *Sep 21 18:27:05.575: //397/164A2EC08230/CCAPI/cc_api_call_disconnect_done: Call Disconnect Event Sent *Sep 21 18:27:05.575: //397/164A2EC08230/SIP/State/sipSPIChangeState: 0x44E4A210 : State change from (STATE_DISCONNECTING, SUBSTATE_NONE) to (STATE_DEAD, SUBSTATE_NONE) *Sep 21 18:27:05.575: //397/164A2EC08230/SIP/Call/sipSPICallInfo: The Call Setup Information is: Call Control Block (CCB) : 0x44E4A210 State of The Call : STATE_DEAD TCP Sockets Used : NO Calling Number : Called Number : 6105559999 Source IP Address (Sig ): 206.231.245.253 Destn SIP Req Addr:Port : 65.72.32.5:5060 Destn SIP Resp Addr:Port : 65.72.32.5:5060 Destination Name : 65.72.32.5 *Sep 21 18:27:05.575: //397/164A2EC08230/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): 206.231.245.253 Source IP Port (Media): 18866 Destn IP Address (Media): 65.72.32.5 Destn IP Port (Media): 36912 Orig Destn IP Address:Port (Media): 0.0.0.0:0 *Sep 21 18:27:05.575: //397/164A2EC08230/SIP/Call/sipSPICallInfo: Disconnect Cause (CC) : 44 Disconnect Cause (SIP) : 500 *Sep 21 18:27:05.575: //397/164A2EC08230/SIP/Info/sipSPIUdeleteccCallIdFromTable: Removing call id 18D *Sep 21 18:27:05.579: //397/164A2EC08230/SIP/Info/sipSPIUdeleteCcbFromUASReqTable: ****Deleting from UAS Request table. *Sep 21 18:27:05.579: //397/164A2EC08230/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x44E4A210 key=BW1428089292109071866666989@206.161.122.76105559999 *Sep 21 18:27:05.579: //397/164A2EC08230/SIP/Info/sipSPIUdeleteCcbFromUASRespTable: ****Deleting from UAS Response table. *Sep 21 18:27:05.579: //397/164A2EC08230/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x44E4A210 key=BW1428089292109071866666989@206.161.122.711F54038-1CC4 *Sep 21 18:27:05.579: //397/164A2EC08230/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd *Sep 21 18:27:05.579: //397/164A2EC08230/SIP/Info/sipSPIUfreeOneCCB: Freeing ccb 44E4A210 *Sep 21 18:27:14.155: //-1/000000000000/SIP/State/sipSPIChangeState: 0x46D81C4C : State change from (STATE_NONE, SUBSTATE_NONE) to (SIP_STATE_OUTGOING_REGISTER, SUBSTATE_NONE) *Sep 21 18:27:14.155: //-1/000000000000/SIP/Info/sipSPIUaddCcbToUACTable: ****Adding to UAC table. *Sep 21 18:27:14.155: //-1/000000000000/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x46D81C4C key=D39FE7C3-679311DC-8203841B-4392E3BF *Sep 21 18:27:14.155: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Clock Time Zone is UTC, same as GMT: Using GMT *Sep 21 18:27:14.155: //-1/000000000000/SIP/Transport/sipSPISendRegister: Sending REGISTER to the transport layer *Sep 21 18:27:14.155: //-1/000000000000/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Global configuration, Switch Transport is FALSE *Sep 21 18:27:14.155: //-1/000000000000/SIP/Transport/sipSPITransportSendMessage: msg=0x45A63434, addr=206.161.122.8, port=5060, sentBy_port=0, is_req=1, transport=1, switch=0, callBack=0x4106A0B8 *Sep 21 18:27:14.155: //-1/000000000000/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately *Sep 21 18:27:14.159: //-1/000000000000/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0 *Sep 21 18:27:14.159: //-1/000000000000/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x45A63434 *Sep 21 18:27:14.159: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x45A63434, addr=206.161.122.8, port=5060, connId=2 for UDP *Sep 21 18:27:14.159: //-1/000000000000/SIP/State/sipSPIChangeState: 0x46D81C4C : State change from (SIP_STATE_OUTGOING_REGISTER, SUBSTATE_NONE) to (SIP_STATE_OUTGOING_REGISTER, SUBSTATE_NONE) *Sep 21 18:27:14.159: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg: Sent: