uc520 transcoding on g711alaw sip trunk?

Unanswered Question
Sep 17th, 2009

Hi,

I have a setup where i need to translate g711alaw sip trunk traffic towards the CUE (that only supports g711ulaw). Normal calling/transfers etc. are ok, but access from a incoming (sip-trunk) call to the voicemail on the CUE fails (no codec). I would like to transcode the traffic to G711ulaw so it can reach the voicemail.


However, my transcoding solution does not funtion correctly:
The 'sh sccp' and 'sh dspfarm' commands give the following: it seems that the dsp resources are not correctly associated to the sccp process.

UC520#sh sccp
SCCP Admin State: UP
Gateway IP Address: 10.1.10.2, Port Number: 2000
IP Precedence: 3
User Masked Codec list: None
Call Manager: 10.1.10.1, Port Number: 2000
                Priority: N/A, Version: 3.1, Identifier: 1
                Trustpoint: N/A
Transcoding Oper State: ACTIVE_IN_PROGRESS - Cause Code: TCP_CONN_ERROR
Active Call Manager: NONE
TCP Link Status: NOT_CONNECTED, Profile Identifier: 1
Reported Max Streams: 20, Reported Max OOS Streams: 0
Supported Codec: g711ulaw, Maximum Packetization Period: 30
Supported Codec: rfc2833 dtmf, Maximum Packetization Period: 30
Supported Codec: rfc2833 pass-thru, Maximum Packetization Period: 30
Supported Codec: inband-dtmf to rfc2833 conversion, Maximum Packetization Period: 30

UC520#

UC520#sh dspfarm all
Dspfarm Profile Configuration
Profile ID = 1, Service = TRANSCODING, Resource ID = 1 
Profile Description : 
Profile Service Mode : Non Secure
Profile Admin State : UP
Profile Operation State : ACTIVE IN PROGRESS
Application : SCCP   Status : ASSOCIATION IN PROGRESS
Resource Provider : FLEX_DSPRM   Status : UP
Number of Resource Configured : 10
Number of Resource Available : 10
Codec Configuration
Codec : g711ulaw, Maximum Packetization Period : 30

SLOT DSP VERSION  STATUS CHNL USE   TYPE    RSC_ID BRIDGE_ID PKTS_TXED PKTS_RXED
0    1   23.8.0   UP     N/A  FREE  xcode  1      -         -         -       
0    1   23.8.0   UP     N/A  FREE  xcode  1      -         -         -       
0    1   23.8.0   UP     N/A  FREE  xcode  1      -         -         -       
0    1   23.8.0   UP     N/A  FREE  xcode  1      -         -         -       
0    1   23.8.0   UP     N/A  FREE  xcode  1      -         -         -       
0    2   23.8.0   UP     N/A  FREE  xcode  1      -         -         -       
0    2   23.8.0   UP     N/A  FREE  xcode  1      -         -         -       
0    2   23.8.0   UP     N/A  FREE  xcode  1      -         -         -       
0    2   23.8.0   UP     N/A  FREE  xcode  1      -         -         -       
0    2   23.8.0   UP     N/A  FREE  xcode  1      -         -         -       
Total number of DSPFARM DSP channel(s) 10
UC520#

Relevant parts of the config:

interface Loopback0
description $FW_INSIDE$
ip address 10.1.10.2 255.255.255.252
ip virtual-reassembly
!
interface Integrated-Service-Engine0/0
description cue is initialized with default IMAP group
ip unnumbered Loopback0
ip virtual-reassembly
service-module ip address 10.1.10.1 255.255.255.252
service-module ip default-gateway 10.1.10.2
!
voice-card 0
no dspfarm
dsp services dspfarm
!
sccp local Loopback0
sccp ccm 10.1.10.1 identifier 1
sccp ip precedence 3
sccp
!
sccp ccm group 1
bind interface Loopback0
associate ccm 1 priority 1
associate profile 1 register MTP001B8FA84BA0 <= MAC intf in0/0
keepalive retries 5
switchover method immediate
switchback method immediate
switchback interval 15
!
dspfarm profile 1 transcode 
codec g711ulaw
maximum sessions 10
associate application SCCP
!
telephony-service
sdspfarm units 5
sdspfarm transcode sessions 128
sdspfarm tag 1 MTP001B8FA84BA0

Thanks for the help!

/Edwin

I have this problem too.
0 votes
  • 1
  • 2
  • 3
  • 4
  • 5
Overall Rating: 0 (0 ratings)
Loading.
Marcos Hernandez Thu, 09/17/2009 - 10:51

Edwin,

Can you add the following keyword to this command:

sccp ccm 10.1.1.1 identifier 1 version 4.1

Let me know if that helps.


Marcos

edwinkoning Thu, 09/17/2009 - 12:21

Marcos,

I made the changes you suggested:

---

sccp local Loopback0
sccp ccm 10.1.1.1 identifier 1 version 4.1
sccp ip precedence 3
sccp
!
sccp ccm group 1
bind interface Loopback0
associate ccm 1 priority 1
associate profile 1 register MTP00000C4588E8
keepalive retries 5
switchover method immediate
switchback method immediate
switchback interval 15
!
dspfarm profile 1 transcode 
codec g711alaw
codec g711ulaw
maximum sessions 10
associate application SCCP
---

Situation has improved:

UC520#sh sccp
SCCP Admin State: UP
Gateway IP Address: 10.1.10.2, Port Number: 2000
IP Precedence: 3
User Masked Codec list: None
Call Manager: 10.1.1.1, Port Number: 2000
                Priority: N/A, Version: 4.1, Identifier: 1
                Trustpoint: N/A

Transcoding Oper State: ACTIVE - Cause Code: NONE
Active Call Manager: 10.1.1.1, Port Number: 2000
TCP Link Status: CONNECTED, Profile Identifier: 1
Reported Max Streams: 20, Reported Max OOS Streams: 0
Supported Codec: g711alaw, Maximum Packetization Period: 30
Supported Codec: g711ulaw, Maximum Packetization Period: 30
Supported Codec: rfc2833 dtmf, Maximum Packetization Period: 30
Supported Codec: rfc2833 pass-thru, Maximum Packetization Period: 30
Supported Codec: inband-dtmf to rfc2833 conversion, Maximum Packetization Period: 30

UC520#sh sds
UC520#sh sdspfarm units

mtp-1 Device: TCP socket:[3]  UNREGISTERED
actual_stream:0 max_stream 20 IP:10.1.10.2  56095  MTP Dixieland keepalive 23

mtp-2 Device:MTP00000C4588E8 TCP socket:[3]  REGISTERED in SCCP ver 10/10
actual_stream:20 max_stream 20 IP:10.1.10.2  59177  MTP Dixieland keepalive 9 
Supported codec:
                 G711Ulaw
                 G711Alaw

mtp-3 Device:MTA00000C4588e8 TCP socket:[3]  UNREGISTERED
actual_stream:0 max_stream 20 IP:10.1.10.2  62899  MTP Dixieland keepalive 15

max-mtps:5, max-streams:256, alloc-streams:20, act-streams:0
UC520#

Calls however still fail. In the debug ccsip it looks like the xcode works for the incoming g711a call:

Sep 17 19:23:18.939: //105/63E5D25580DB/SIP/Info/sipSPI_ipip_copy_channelInfo_to_sdp:
need transcoding for codec mismatch
Sep 17 19:23:18.939: //105/63E5D25580DB/SIP/Info/sipSPIDtmfTranscoder: local DTMF 6, peer DTMF 6
Sep 17 19:23:18.939: //105/63E5D25580DB/SIP/Info/sipSPIDtmfTranscoder: local codec 5, peer codec 6
Sep 17 19:23:18.939: //105/63E5D25580DB/SIP/Info/ccsip_do_xcode_stream_ind:
ccsip_do_xcode_stream_ind: Call 105 send CC_EV_H245_SET_XCODE_STREAM: stream 12
Sep 17 19:23:18.939: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_event_handler: 
Sep 17 19:23:18.939: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_event_handler: switch(ev.ev_id: 160)
Sep 17 19:23:18.939: //104/DB9C10F6B08C/SIP/Info/ccsip_event_handler:
ccsip_event_handler: peer ID 105 chans 0x862C53E8 event 160 flags 0x844001C 0x300 0x400403 data 0x862C53E8
Sep 17 19:23:18.939: //104/DB9C10F6B08C/SIP/Info/ccsip_event_handler:
ccsip_event_handler: CC_EV_H245_SET_XCODE_STREAM: peer ID 105, event 160 flags 0x844001C 0x300 0x400403 data 0x862C53E8, type = 1
Sep 17 19:23:18.939: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_MEDIA_XCODE
Sep 17 19:23:18.939: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_event_handler: CC_R_SUCCESS_WITH_CONFIRMED
Sep 17 19:23:18.943: //105/63E5D25580DB/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 10.1.10.2
Sep 17 19:23:18.943: //-1/xxxxxxxxxxxx/SIP/Media/sipSPIReserveRtpPort: reserved port 19532 for stream 1
Sep 17 19:23:18.943: //105/63E5D25580DB/SIP/Media/sipSPIAddSDPMediaPayload: Preferred method of dtmf relay is: 6, with payload: 101
Sep 17 19:23:18.943: //105/63E5D25580DB/SIP/Info/sipSPIAddSDPPayloadAttributes:
max_event 16
Sep 17 19:23:18.943: //-1/xxxxxxxxxxxx/SIP/Info/convert_codec_bytes_to_ptime: Values :Codec: g711ulaw codecbytes :160, ptime: 20

Unfortunately, the call does not end-up in the voicemail though... Must be some other config i guess....

/Edwin

Maulik Shah Thu, 09/17/2009 - 21:47

Can you post the complete debug log (deb ccsip all / deb voip dialpeer inout) for one such failed call?

I think your transcoder config is fine after the change Marcos suggested. FYI - if you choose BT as the SP in the SIP Trunk drop down, you could see a sample config for g711alaw to g711ulaw transcoding

edwinkoning Fri, 09/18/2009 - 00:32

Hello Maulik,

Below is the trace (i replaced my mobile number). Dial-peer for the voicemail is 2000. Voicemail number is 500. Incoming dial-peer for the sip trunk is 3008. I call a phone (ext. 201) that has a forward to the voicemail.

/Edwin

UC520#
Sep 18 07:19:47.556: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpSocketReads: Msg enqueued for SPI with IP addr: 213.239.5.68:5060
Sep 18 07:19:47.556: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1
Sep 18 07:19:47.556: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x00000000
Sep 18 07:19:47.556: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
INVITE sip:[email protected]:5060 SIP/2.0
Record-Route:
Via: SIP/2.0/UDP 213.239.5.68;branch=z9hG4bKc407.82ea18f.0
Via: SIP/2.0/UDP 213.239.5.69;branch=z9hG4bK24542412134
Via: SIP/2.0/UDP  212.4.211.245:5060;x-route-tag="cid:[email protected]";branch=z9hG4bK24542412134
From: ;tag=17F9C2A8-1A30
To:
Date: Fri, 18 Sep 2009 07:08:50 GMT
Call-ID: [email protected]
Supported: 100rel,timer,replaces
Min-SE:  1800
Cisco-Guid: 4089194944-2740457950-2586378266-2730347454
User-Agent: Cisco-SIPGateway/IOS-12.x
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO, UPDATE, REGISTER
CSeq: 101 INVITE
Max-Forwards: 68
Timestamp: 1253257730
Contact:
Expires: 180
Allow-Events: telephone-event
Content-Type: application/sdp
Content-Length: 271
To-Hint: sip:[email protected]
From-Hint: sip:+[phonenumber]@test.winitu.com
P-hint: usrloc applied
Remote-Party-ID: ;party=calling;screen=yes

v=0
o=CiscoSystemsSIP-GW-UserAgent 7901 8182 IN IP4 212.4.211.245
s=SIP Call
c=IN IP4 212.4.211.245
t=0 0
m=audio 17764 RTP/AVP 8 101
c=IN IP4 212.4.211.245
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=direction:passive

Sep 18 07:19:47.556: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog
Sep 18 07:19:47.560: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAddContextToTable: Added context(0x8649C07C) with key=[386] to table
Sep 18 07:19:47.560: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 213.239.5.68,Port 5060, Tr
ansport 1, SentBy Port 5060
Sep 18 07:19:47.560: //-1/F3BC29C09A29/SIP/State/sipSPIChangeState: 0x8649C07C : State change from (STATE_NONE, SUBSTATE_NONE)  to (
STATE_IDLE, SUBSTATE_NONE)
Sep 18 07:19:47.560: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 213.239.5.68,Port 5060, Tr
ansport 1, SentBy Port 5060
Sep 18 07:19:47.560: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Converting TimeZone PST to SIP default timezone = GMT
Sep 18 07:19:47.560: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 213.239.5.68,Port 5060, Tr
ansport 1, SentBy Port 5060
Sep 18 07:19:47.560: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
   Calling Number=student2, Called Number=student2, Peer Info Type=DIALPEER_INFO_SPEECH
Sep 18 07:19:47.560: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
   Match Rule=DP_MATCH_DEST; Called Number=student2
Sep 18 07:19:47.560: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
   No Outgoing Dial-peer Is Matched; Result=NO_MATCH(-1)
Sep 18 07:19:47.560: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersMoreArg:
   Result=NO_MATCH(-1)
Sep 18 07:19:47.560: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentGTD: No GTD found in inbound container
Sep 18 07:19:47.560: //-1/F3BC29C09A29/SIP/Info/sipSPIUaddCcbToUASReqTable: ****Adding to UAS Request table.
Sep 18 07:19:47.560: //-1/F3BC29C09A29/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x8649C07C key=F3BCC5E8-A35811DE-913CC32C-
[email protected]
Sep 18 07:19:47.560: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeerCore:
   Calling Number=+[phonenumber], Called Number=, Voice-Interface=0x0,
   Timeout=TRUE, Peer Encap Type=ENCAP_VOIP, Peer Search Type=PEER_TYPE_VOICE,
   Peer Info Type=DIALPEER_INFO_SPEECH
Sep 18 07:19:47.560: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeerCore:
   Result=NO_MATCH(-1) After All Match Rules Attempt
Sep 18 07:19:47.560: //-1/F3BC29C09A29/SIP/Info/sipSPIMatchSrcIpGroup: Match not found on carrier id
Sep 18 07:19:47.560: //-1/F3BC29C09A29/SIP/Info/sipSPIMatchSrcIpGroup: Match not found on Incoming called number: student2
Sep 18 07:19:47.560: //-1/F3BC29C09A29/SIP/Info/sipSPIMatchSrcIpGroup: Match not found on destination pattern: +[phonenumber]
Sep 18 07:19:47.560: //-1/F3BC29C09A29/SIP/Info/ccsipUpdateIncomingCallParams: ccCallInfo: Calling name , number +[phonenumber], Calli
ng oct3 0x00, oct_3a 0x80, Called number student2
Sep 18 07:19:47.564: ccDumpTdRequestDataSip:
Sep 18 07:19:47.564: reqURI=sip:[email protected]:5060
Sep 18 07:19:47.564: calling_urip=sip:+[phonenumber]@test.winitu.com
Sep 18 07:19:47.564: url_dump_header_line_avpair:
Sep 18 07:19:47.564:   num_headers = 23
Sep 18 07:19:47.564:     headers[0].linep = From:;tag=17F9C2A8-1A30, len = 57
Sep 18 07:19:47.564:       data.attr.datap = From:;tag=17F9C2A8-1A30, len = 4
Sep 18 07:19:47.564:       data.value.datap = ;tag=17F9C2A8-1A30, len = 52
Sep 18 07:19:47.564:     headers[1].linep = To:, len = 33
Sep 18 07:19:47.564:       data.attr.datap = To:, len = 2
Sep 18 07:19:47.564:       data.value.datap = , len = 30
Sep 18 07:19:47.564:     headers[2].linep = Via:SIP/2.0/UDP 213.239.5.68;branch=z9hG4bKc407.82ea18f.0,SIP/2.0/UDP 213.239.5.69;branc
h=z9hG4bK24542412134,SIP/2.0/UDP  212.4.211.245:5060;x-route-tag="cid:[email protected]";branch=z9hG4bK24542412134, len = 208
Sep 18 07:19:47.564:       data.attr.datap = Via:SIP/2.0/UDP 213.239.5.68;branch=z9hG4bKc407.82ea18f.0,SIP/2.0/UDP 213.239.5.69;bran
ch=z9hG4bK24542412134,SIP/2.0/UDP  212.4.211.245:5060;x-route-tag="cid:[email protected]";branch=z9hG4bK24542412134, len = 3
Sep 18 07:19:47.564:       data.value.datap = SIP/2.0/UDP 213.239.5.68;branch=z9hG4bKc407.82ea18f.0,SIP/2.0/UDP 213.239.5.69;branch=
z9hG4bK24542412134,SIP/2.0/UDP  212.4.211.245:5060;x-route-tag="cid:[email protected]";branch=z9hG4bK24542412134, len = 204
Sep 18 07:19:47.564:     headers[3].linep = Call-Id:[email protected], len = 57
Sep 18 07:19:47.564:       data.attr.datap = Call-Id:[email protected], len = 7
Sep 18 07:19:47.564:       data.value.datap = [email protected], len = 49
Sep 18 07:19:47.564:     headers[4].linep = Cseq:101 INVITE, len = 15
Sep 18 07:19:47.564:       data.attr.datap = Cseq:101 INVITE, len = 4
Sep 18 07:19:47.564:       data.value.datap = 101 INVITE, len = 10
Sep 18 07:19:47.564:     headers[5].linep = Contact:, len = 43
Sep 18 07:19:47.564:       data.attr.datap = Contact:, len = 7
Sep 18 07:19:47.564:       data.value.datap = , len = 35
Sep 18 07:19:47.564:     headers[6].linep = Content-Length:271, len = 18
Sep 18 07:19:47.564:       data.attr.datap = Content-Length:271, len = 14
Sep 18 07:19:47.564:       data.value.datap = 271, len = 3
Sep 18 07:19:47.564:     headers[7].linep = Content-Type:application/sdp, len = 28
Sep 18 07:19:47.564:       data.attr.datap = Content-Type:application/sdp, len = 12
Sep 18 07:19:47.564:       data.value.datap = application/sdp, len = 15
Sep 18 07:19:47.564:     headers[8].linep = Record-Route:HEZYQFtAQC5jb20->, len = 105
Sep 18 07:19:47.564:       data.attr.datap = Record-Route:aHEZYQFtAQC5jb20->, len = 12
Sep 18 07:19:47.564:       data.value.datap = jb20->, len = 92
Sep 18 07:19:47.564:     headers[9].linep = Date:Fri, 18 Sep 2009 07:08:50 GMT, len = 34
Sep 18 07:19:47.564:       data.attr.datap = Date:Fri, 18 Sep 2009 07:08:50 GMT, len = 4
Sep 18 07:19:47.564:       data.value.datap = Fri, 18 Sep 2009 07:08:50 GMT, len = 29
Sep 18 07:19:47.564:     headers[10].linep = Supported:100rel,timer,replaces, len = 31
Sep 18 07:19:47.564:       data.attr.datap = Supported:100rel,timer,replaces, len = 9
Sep 18 07:19:47.564:       data.value.datap = 100rel,timer,replaces, len = 21
Sep 18 07:19:47.564:     headers[11].linep = Min-SE:1800, len = 11
Sep 18 07:19:47.564:       data.attr.datap = Min-SE:1800, len = 6
Sep 18 07:19:47.564:       data.value.datap = 1800, len = 4
Sep 18 07:19:47.564:     headers[12].linep = Cisco-Guid:4089194944-2740457950-2586378266-2730347454, len = 54
Sep 18 07:19:47.564:       data.attr.datap = Cisco-Guid:4089194944-2740457950-2586378266-2730347454, len = 10
Sep 18 07:19:47.564:       data.value.datap = 4089194944-2740457950-2586378266-2730347454, len = 43
Sep 18 07:19:47.564:     headers[13].linep = User-Agent:Cisco-SIPGateway/IOS-12.x, len = 36
Sep 18 07:19:47.564:       data.attr.datap = User-Agent:Cisco-SIPGateway/IOS-12.x, len = 10
Sep 18 07:19:47.564:       data.value.datap = Cisco-SIPGateway/IOS-12.x, len = 25
Sep 18 07:19:47.564:     headers[14].linep = Allow:INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO,
UPDATE, REGISTER, len = 103
Sep 18 07:19:47.564:       data.attr.datap = Allow:INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO,
UPDATE, REGISTER, len = 5
Sep 18 07:19:47.564:       data.value.datap = INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO, UPDAT
E, REGISTER, len = 97
Sep 18 07:19:47.564:     headers[15].linep = Max-Forwards:68, len = 15
Sep 18 07:19:47.564:       data.attr.datap = Max-Forwards:68, len = 12
Sep 18 07:19:47.564:       data.value.datap = 68, len = 2
Sep 18 07:19:47.564:     headers[16].linep = Timestamp:1253257730, len = 20
Sep 18 07:19:47.564:       data.attr.datap = Timestamp:1253257730, len = 9
Sep 18 07:19:47.564:       data.value.datap = 1253257730, len = 10
Sep 18 07:19:47.564:     headers[17].linep = Expires:180, len = 11
Sep 18 07:19:47.564:       data.attr.datap = Expires:180, len = 7
Sep 18 07:19:47.564:       data.value.datap = 180, len = 3
Sep 18 07:19:47.564:     headers[18].linep = Allow-Events:telephone-event, len = 28
Sep 18 07:19:47.564:       data.attr.datap = Allow-Events:telephone-event, len = 12
Sep 18 07:19:47.564:       data.value.datap = telephone-event, len = 15
Sep 18 07:19:47.564:     headers[19].linep = To-Hint:sip:[email protected], len = 36
Sep 18 07:19:47.564:       data.attr.datap = To-Hint:sip:[email protected], len = 7
Sep 18 07:19:47.564:       data.value.datap = sip:[email protected], len = 28
Sep 18 07:19:47.564:     headers[20].linep = From-Hint:sip:+[phonenumber]@test.winitu.com, len = 42
Sep 18 07:19:47.564:       data.attr.datap = From-Hint:sip:+[phonenumber]@test.winitu.com, len = 9
Sep 18 07:19:47.564:       data.value.datap = sip:+[phonenumber]@test.winitu.com, len = 32
Sep 18 07:19:47.564:     headers[21].linep = P-hint:usrloc applied, len = 21
Sep 18 07:19:47.564:       data.attr.datap = P-hint:usrloc applied, len = 6
Sep 18 07:19:47.564:       data.value.datap = usrloc applied, len = 14
Sep 18 07:19:47.564:     headers[22].linep = Remote-Party-ID:;party=calling;screen=yes, len = 75
Sep 18 07:19:47.564:       data.attr.datap = Remote-Party-ID:;party=calling;screen=yes, len = 15
Sep 18 07:19:47.564:       data.value.datap = ;party=calling;screen=yes, len = 59num_bodies = 0
Sep 18 07:19:47.564: //-1/F3BC29C09A29/SIP/Info/sipSPIGetShrlPeer: Try match incoming dialpeer for Calling number: : +[phonenumber]
Sep 18 07:19:47.568: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeerCore:
   Calling Number=+[phonenumber], Called Number=, Voice-Interface=0x0,
   Timeout=TRUE, Peer Encap Type=ENCAP_VOIP, Peer Search Type=PEER_TYPE_VOICE,
   Peer Info Type=DIALPEER_INFO_SPEECH
Sep 18 07:19:47.568: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeerCore:
   Result=NO_MATCH(-1) After All Match Rules Attempt
Sep 18 07:19:47.568: //-1/F3BC29C09A29/DPM/dpAssociateIncomingPeerCore:
   Calling Number=+[phonenumber], Called Number=student2, Voice-Interface=0x0,
   Timeout=TRUE, Peer Encap Type=ENCAP_VOIP, Peer Search Type=PEER_TYPE_VOICE,
   Peer Info Type=DIALPEER_INFO_SPEECH
Sep 18 07:19:47.568: //-1/F3BC29C09A29/DPM/dpAssociateIncomingPeerCore:
   Result=Success(0) after DP_MATCH_TO_URI; Incoming Dial-peer=3008
Sep 18 07:19:47.568: //-1/F3BC29C09A29/SIP/Info/sipSPIGetCallConfig: Peer tag 3008 matched for incoming call
Sep 18 07:19:47.568: //-1/F3BC29C09A29/SIP/Info/sipSPIGetCallConfig: Precondition tag absent in Require/Supported header
Sep 18 07:19:47.568: //-1/F3BC29C09A29/SIP/Info/sipSPIGetCallConfig: Using Voice Class Codec, tag = 1
Sep 18 07:19:47.568: //-1/F3BC29C09A29/SIP/Info/sipSPIGetCallConfig: xcoder high-density disabled
Sep 18 07:19:47.568: //-1/F3BC29C09A29/SIP/Info/sipSPIGetCallConfig: Flow Mode set to FLOW_THROUGH
Sep 18 07:19:47.568: //-1/F3BC29C09A29/SIP/Info/sipSPIContinueNewMsgInvite: Calling name , number +[phonenumber], Calling oct3 0x00, o
ct_3a 0x80, ext_priv 0x00, Called number student2, oct3 0x00
Sep 18 07:19:47.568: //-1/F3BC29C09A29/SIP/Info/sipSPIContinueNewMsgInvite: Carrier id code , prev_cid DMS-TRUNK, next_cid NONE, pre
v_tgrp NONE, next_tgrp NONE
Sep 18 07:19:47.568: //-1/F3BC29C09A29/SIP/Info/sipSPIContinueNewMsgInvite: Requires reliable-provisional support
Sep 18 07:19:47.568: //-1/F3BC29C09A29/SIP/Info/sipSPIRscmsmAvail: Value returned by check is = 1
Sep 18 07:19:47.568: //397/F3BC29C09A29/SIP/Info/sipSPINegotiateSessionExpires: Min-SE Header: 1800
Sep 18 07:19:47.568: //397/F3BC29C09A29/SIP/Info/sipSPIDoMediaNegotiation: Number of m-lines = 1
Sep 18 07:19:47.568: //397/F3BC29C09A29/SIP/Info/sipSPIDoAudioNegotiation: Codec (g711alaw) Negotiation Successful on Static Payload
for m-line 1
Sep 18 07:19:47.568: //397/F3BC29C09A29/SIP/Info/sipSPIDoPtimeNegotiation: One ptime attribute found - value:20
Sep 18 07:19:47.568: //-1/xxxxxxxxxxxx/SIP/Info/convert_ptime_to_codec_bytes: Values :Codec: g711alaw ptime :20, codecbytes: 160
Sep 18 07:19:47.568: //-1/xxxxxxxxxxxx/SIP/Info/convert_codec_bytes_to_ptime: Values :Codec: g711alaw codecbytes :160, ptime: 20
Sep 18 07:19:47.568: //397/F3BC29C09A29/SIP/Media/sipSPIDoPtimeNegotiation: Offered ptime:20, Negotiated ptime:20 Negotiated codec b
ytes: 160 for codec g711alaw
Sep 18 07:19:47.568: //397/F3BC29C09A29/SIP/Info/sipSPIDoDTMFRelayNegotiation: m-line index 1
Sep 18 07:19:47.568: //397/F3BC29C09A29/SIP/Info/sipSPICheckDynPayloadUse: Dynamic payload(101) could not be reserved.
Sep 18 07:19:47.568: //397/F3BC29C09A29/SIP/Info/sipSPIDoDTMFRelayNegotiation: RTP-NTE DTMF relay option
Sep 18 07:19:47.568: //397/F3BC29C09A29/SIP/Info/sipSPIDoDTMFRelayNegotiation: Case of full named event(NE) match in fmtp list of ev
ents.
Sep 18 07:19:47.568: //-1/xxxxxxxxxxxx/SIP/Info/sip_sdp_get_modem_relay_cap_params: NSE payload from X-cap = 0
Sep 18 07:19:47.568: //397/F3BC29C09A29/SIP/Info/sip_select_modem_relay_params: X-tmr not present in SDP. Disable modem relay
Sep 18 07:19:47.568: //397/F3BC29C09A29/SIP/Info/sipSPIGetSDPDirectionAttribute: Parsed the media direction role as:0
Sep 18 07:19:47.568: //397/F3BC29C09A29/SIP/Info/sipSPIDoAudioNegotiation: Codec negotiation successful for media line 1
        payload_type=8, codec_bytes=160, codec=g711alaw, dtmf_relay=rtp-nte
        stream_type=voice+dtmf (1), dest_ip_address=212.4.211.245, dest_port=17764
Sep 18 07:19:47.568: //397/F3BC29C09A29/SIP/State/sipSPIChangeStreamState: Stream (callid =  -1)  State changed from (STREAM_DEAD) t
o (STREAM_ADDING)
Sep 18 07:19:47.568: //397/F3BC29C09A29/SIP/Media/sipSPIUpdCallWithSdpInfo:
        Preferred Codec        : g711alaw, bytes :160
        Preferred  DTMF relay  : rtp-nte
        Preferred NTE payload  : 101
        Early Media            : No
        Delayed Media          : No
        Bridge Done            : No
        New Media              : No
        DSP DNLD Reqd          : No

Sep 18 07:19:47.568: //397/F3BC29C09A29/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 85.223.63.163
Sep 18 07:19:47.568: //397/F3BC29C09A29/SIP/Info/sipSPI_ipip_report_media_to_peer:
callId 397 peer 0 flags 0x201 state STATE_IDLE
Sep 18 07:19:47.568: //397/F3BC29C09A29/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo:
CallID 397, sdp 0x86B81FC8 channels 0x8649D1B0
Sep 18 07:19:47.568: //397/F3BC29C09A29/SIP/Info/copy_channels:
callId 397 size 0 ptr 0x84D7E4B8)
Sep 18 07:19:47.572: //397/F3BC29C09A29/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo:
Hndl ptype 8 mline 1
Sep 18 07:19:47.572: //397/F3BC29C09A29/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: Selecting codec g711alaw
Sep 18 07:19:47.572: //397/F3BC29C09A29/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: ADD AUDIO CODEC 6

Sep 18 07:19:47.572: //-1/xxxxxxxxxxxx/SIP/Info/convert_codec_bytes_to_ptime: Values :Codec: g711alaw codecbytes :160, ptime: 20
Sep 18 07:19:47.572: //397/F3BC29C09A29/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: Media negotiation done: stream->negotiated_pti
me=20,stream->negotiated_codec_bytes=160, coverted ptime=20 stream->mline_index=1, media_ndx=1
Sep 18 07:19:47.572: //397/F3BC29C09A29/SIP/Error/sipSPI_ipip_copy_sdp_to_channelInfo:
failed to update call entry
Sep 18 07:19:47.572: //397/F3BC29C09A29/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo:
Adding codec 6 ptype 8 time 20, bytes 160  as channel 0 mline 1 ss 1 212.4.211.245:17764
Sep 18 07:19:47.572: //397/F3BC29C09A29/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo:
Hndl ptype 101 mline 1
Sep 18 07:19:47.572: //397/F3BC29C09A29/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: setting ipip_caps DTMF to RFC2833: callid = 39
7, dtmf = 6
Sep 18 07:19:47.572: //397/F3BC29C09A29/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: Copy sdp to channel- AFTER CODEC FILTERING: cc
b->pld.ipip_caps.codecInfo[channel_ndx].codec = 6

Sep 18 07:19:47.572: //397/F3BC29C09A29/SIP/Info/sipSPI_ipip_copy_sdp_to_channelInfo: Copy sdp to channel- AFTER CODEC FILTERING: cc
b->pld.ipip_caps.codecInfo[channel_ndx].codec = -1

Sep 18 07:19:47.572: //397/F3BC29C09A29/SIP/Info/sipSPI_ipip_report_media_to_peer:
callId 397 flags 0x300 state STATE_IDLE
Sep 18 07:19:47.572: //397/F3BC29C09A29/SIP/Info/sipSPI_ipip_report_media_to_peer:
Report initial call media
Sep 18 07:19:47.572: //397/F3BC29C09A29/SIP/Info/sipSPI_ipip_report_media_to_peer: ccb->flags 0x804000C, ccb->pld.flags_ipip 0x201

Sep 18 07:19:47.572: //397/F3BC29C09A29/SIP/Info/copy_channels:
callId 397 size 224 ptr 0x8706A280)
Sep 18 07:19:47.572: //397/F3BC29C09A29/SIP/Info/sipSPI_ipip_report_media_to_peer:
CCSIP: Unable to report channel ind
Sep 18 07:19:47.572: //397/F3BC29C09A29/SIP/Info/ccsip_update_srtp_caps:  4223: Posting Remote SRTP caps to other callleg.
Sep 18 07:19:47.572: //397/F3BC29C09A29/SIP/Media/sipSPIUpdCallWithSdpInfo:
          Stream type            : voice+dtmf
          Media line             : 1
          State                  : STREAM_ADDING (2)
          Callid                 : -1
          Negotiated Codec       : g711alaw, bytes :160
          Nego. Codec payload    : 8 (tx), 8 (rx)
          Negotiated DTMF relay  : rtp-nte
          Negotiated NTE payload : 101 (tx), 101 (rx)
          Negotiated CN payload  : 0
          Media Srce Addr/Port   : 85.223.63.163:0
          Media Dest Addr/Port   : 212.4.211.245:17764

Sep 18 07:19:47.572: //397/F3BC29C09A29/SIP/Info/sipSPIHandleInviteMedia:
Negotiated Codec       : g711alaw, bytes :160
Preferred Codec        : g711alaw, bytes :160
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 18 07:19:47.572: //397/F3BC29C09A29/SIP/Info/sipSPIDoQoSNegotiation: SDP body with media description
Sep 18 07:19:47.572: //397/F3BC29C09A29/SIP/Info/sipSPICanSetFallbackFlag: Local Fallback is not active
Sep 18 07:19:47.572: //-1/xxxxxxxxxxxx/SIP/Media/sipSPIReserveRtpPort: reserved port 17326 for stream 1
Sep 18 07:19:47.572: //397/F3BC29C09A29/SIP/Info/sipSPIUpdateSrcSdpFixedPart: Reserving rtp port for stream 1, src_port=17326
Sep 18 07:19:47.572: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetMediaDirectionForStream: Setting Media direction SENDRECV for stream 1
Sep 18 07:19:47.572: //397/F3BC29C09A29/SIP/Info/sipSPIUpdateSrcSdpVariablePart: Setting stream 1 portnum to 17326
Sep 18 07:19:47.572: //397/F3BC29C09A29/SIP/Info/sipSPIUpdateSrcSdpVariablePart:
SIP update src sdp, negoitated codec 6, payload type 8

Sep 18 07:19:47.572: //397/F3BC29C09A29/SIP/Info/sipSPIUpdateSrcSdpVariablePart: Negotiated method of dtmf relayand pyld: 6 101

Sep 18 07:19:47.572: //397/F3BC29C09A29/SIP/Info/sipSPIAddBillingInfoToCcb: sipCallId for billing records = F3BCC5E8-A35811DE-913CC3
[email protected]
Sep 18 07:19:47.572: //397/F3BC29C09A29/SIP/Info/sipSPI_ipip_store_channel_info: Store channelInfo in CallInfo
Sep 18 07:19:47.572: //397/F3BC29C09A29/SIP/Info/sipSPI_ipip_store_channel_info: dtmf negotiation done, storing negotiated dtmf = 6,
Sep 18 07:19:47.572: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentQSIG: No QSIG Body found in inbound container
Sep 18 07:19:47.572: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentQ931: No RawMsg Body found in inbound container
Sep 18 07:19:47.572: //-1/xxxxxxxxxxxx/SIP/Info/sipSPICreateNewRawMsg: No Data to form The Raw Message

Sep 18 07:19:47.572: //397/F3BC29C09A29/SIP/Info/ccsip_set_bearer_capability:
   Bearer Capability: Speech (0x00)
Sep 18 07:19:47.572: //397/F3BC29C09A29/SIP/Info/sipSPIContinueNewMsgInvite: ccsip_api_call_setup_ind returned: SIP_SUCCESS
Sep 18 07:19:47.572: //397/F3BC29C09A29/SIP/Info/sipSPIUaddccCallIdToTable: Adding call id 18D to table
Sep 18 07:19:47.576: //397/F3BC29C09A29/SIP/Transport/sipSPITransportSendMessage: msg=0x86CD7F44, addr=213.239.5.68, port=5060, sent
By_port=5060, is_req=0, transport=1, switch=0, callBack=0x00000000
Sep 18 07:19:47.576: //397/F3BC29C09A29/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
Sep 18 07:19:47.576: //397/F3BC29C09A29/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0
Sep 18 07:19:47.576: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x86CD7F44, addr=213.239.5.68
, port=5060, connId=0 for UDP
Sep 18 07:19:47.576: //397/F3BC29C09A29/SIP/State/sipSPIChangeState: 0x8649C07C : State change from (STATE_IDLE, SUBSTATE_NONE)  to
(STATE_RECD_INVITE, SUBSTATE_NONE)
Sep 18 07:19:47.576: //397/F3BC29C09A29/SIP/Info/sipSPIProcessContactInfo: Previous Hop 213.239.5.68:5060
Sep 18 07:19:47.576: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_PROCEEDING
Sep 18 07:19:47.576: //-1/F3BC29C09A29/DPM/dpMatchPeersCore:
   Calling Number=, Called Number=201, Peer Info Type=DIALPEER_INFO_SPEECH
Sep 18 07:19:47.576: //-1/F3BC29C09A29/DPM/dpMatchPeersCore:
   Match Rule=DP_MATCH_DEST; Called Number=201
Sep 18 07:19:47.576: //-1/F3BC29C09A29/DPM/dpMatchPeersCore:
   Result=Success(0) after DP_MATCH_DEST
Sep 18 07:19:47.576: //-1/F3BC29C09A29/DPM/dpMatchPeersMoreArg:
   Result=SUCCESS(0)
   List of Matched Outgoing Dial-peer(s):
     1: Dial-peer Tag=20006
Sep 18 07:19:47.576: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
   Calling Number=201, Called Number=201, Peer Info Type=DIALPEER_INFO_SPEECH
Sep 18 07:19:47.576: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
   Match Rule=DP_MATCH_DEST; Called Number=201
Sep 18 07:19:47.576: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
   Result=Success(0) after DP_MATCH_DEST
Sep 18 07:19:47.576: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersMoreArg:
   Result=SUCCESS(0)
   List of Matched Outgoing Dial-peer(s):
     1: Dial-peer Tag=20006
Sep 18 07:19:47.576: //-1/F3BC29C09A29/DPM/dpMatchPeersCore:
   Calling Number=, Called Number=500, Peer Info Type=DIALPEER_INFO_SPEECH
Sep 18 07:19:47.576: //-1/F3BC29C09A29/DPM/dpMatchPeersCore:
   Match Rule=DP_MATCH_DEST; Called Number=500
Sep 18 07:19:47.580: //-1/F3BC29C09A29/DPM/dpMatchPeersCore:
   Result=Success(0) after DP_MATCH_DEST
Sep 18 07:19:47.580: //-1/F3BC29C09A29/DPM/dpMatchPeersMoreArg:
   Result=SUCCESS(0)
   List of Matched Outgoing Dial-peer(s):
     1: Dial-peer Tag=2000
Sep 18 07:19:47.580: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
   Calling Number=500, Called Number=500, Peer Info Type=DIALPEER_INFO_SPEECH
Sep 18 07:19:47.580: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
   Match Rule=DP_MATCH_DEST; Called Number=500
Sep 18 07:19:47.580: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
   Result=Success(0) after DP_MATCH_DEST
Sep 18 07:19:47.580: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersMoreArg:
   Result=SUCCESS(0)
   List of Matched Outgoing Dial-peer(s):
     1: Dial-peer Tag=2000
Sep 18 07:19:47.580: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeerCore:
   Calling Number=500, Called Number=, Voice-Interface=0x0,
   Timeout=TRUE, Peer Encap Type=ENCAP_VOIP, Peer Search Type=PEER_TYPE_VOICE,
   Peer Info Type=DIALPEER_INFO_SPEECH
Sep 18 07:19:47.580: //-1/xxxxxxxxxxxx/DPM/dpAssociateIncomingPeerCore:
   Result=Success(0) after DP_MATCH_ORIGINATE; Incoming Dial-peer=2000
Sep 18 07:19:47.580: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
   Calling Number=, Called Number=201, Peer Info Type=DIALPEER_INFO_SPEECH
Sep 18 07:19:47.580: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
   Match Rule=DP_MATCH_DEST; Called Number=201
Sep 18 07:19:47.580: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
   Result=Success(0) after DP_MATCH_DEST
Sep 18 07:19:47.580: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersMoreArg:
   Result=SUCCESS(0)
   List of Matched Outgoing Dial-peer(s):
     1: Dial-peer Tag=20006
Sep 18 07:19:47.580: //-1/F3BC29C09A29/DPM/dpMatchPeersCore:
   Calling Number=, Called Number=201, Peer Info Type=DIALPEER_INFO_SPEECH
Sep 18 07:19:47.580: //-1/F3BC29C09A29/DPM/dpMatchPeersCore:
   Match Rule=DP_MATCH_DEST; Called Number=201
Sep 18 07:19:47.580: //-1/F3BC29C09A29/DPM/dpMatchPeersCore:
   Result=Success(0) after DP_MATCH_DEST
Sep 18 07:19:47.580: //-1/F3BC29C09A29/DPM/dpMatchPeersMoreArg:
   Result=SUCCESS(0)
   List of Matched Outgoing Dial-peer(s):
     1: Dial-peer Tag=20006
Sep 18 07:19:47.580: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
   Calling Number=, Called Number=500, Peer Info Type=DIALPEER_INFO_SPEECH
Sep 18 07:19:47.580: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
   Match Rule=DP_MATCH_DEST; Called Number=500
Sep 18 07:19:47.580: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
   Result=Success(0) after DP_MATCH_DEST
Sep 18 07:19:47.580: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersMoreArg:
   Result=SUCCESS(0)
   List of Matched Outgoing Dial-peer(s):
     1: Dial-peer Tag=2000
Sep 18 07:19:47.580: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
   Calling Number=, Called Number=+[phonenumber], Peer Info Type=DIALPEER_INFO_SPEECH
Sep 18 07:19:47.580: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
   Match Rule=DP_MATCH_DEST; Called Number=+[phonenumber]
Sep 18 07:19:47.580: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
   No Outgoing Dial-peer Is Matched; Result=NO_MATCH(-1)
Sep 18 07:19:47.584: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersMoreArg:
   Result=NO_MATCH(-1)
Sep 18 07:19:47.584: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
   Calling Number=, Called Number=500, Peer Info Type=DIALPEER_INFO_SPEECH
Sep 18 07:19:47.584: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
   Match Rule=DP_MATCH_DEST; Called Number=500
Sep 18 07:19:47.584: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
   Result=Success(0) after DP_MATCH_DEST
Sep 18 07:19:47.584: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersMoreArg:
   Result=SUCCESS(0)
   List of Matched Outgoing Dial-peer(s):
     1: Dial-peer Tag=2000
Sep 18 07:19:47.584: //-1/7B2119E08174/DPM/dpMatchPeersCore:
   Calling Number=, Called Number=500, Peer Info Type=DIALPEER_INFO_SPEECH
Sep 18 07:19:47.584: //-1/7B2119E08174/DPM/dpMatchPeersCore:
   Match Rule=DP_MATCH_DEST; Called Number=500
Sep 18 07:19:47.584: //-1/7B2119E08174/DPM/dpMatchPeersCore:
   Result=Success(0) after DP_MATCH_DEST
Sep 18 07:19:47.584: //-1/7B2119E08174/DPM/dpMatchPeersMoreArg:
   Result=SUCCESS(0)
   List of Matched Outgoing Dial-peer(s):
     1: Dial-peer Tag=2000
Sep 18 07:19:47.584: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAddContextToTable: Added context(0x864972A8) with key=[387] to table
Sep 18 07:19:47.584: //398/000000000000/SIP/State/sipSPIChangeState: 0x864972A8 : State change from (STATE_NONE, SUBSTATE_NONE)  to
(STATE_IDLE, SUBSTATE_NONE)
Sep 18 07:19:47.584: //398/000000000000/SIP/Info/ccsip_call_setup_request: Before processing SETUP REQccb->pld.flags_ipip = 200
Sep 18 07:19:47.584: //398/000000000000/SIP/Info/ccsip_call_setup_request:
This a IPIP call: Chan 0, codec 6 channel 17764, ip D404D3F5:17764  params 0x87EC3248 caps 0x870589A4
Sep 18 07:19:47.584: //398/000000000000/SIP/Info/ccsip_gw_set_sipspi_mode: Setting SPI mode to SIP-SIP
Sep 18 07:19:47.584: //398/000000000000/SIP/Info/ccsip_call_setup_request: After processing SETUP REQccb->pld.flags_ipip = 400000
Sep 18 07:19:47.588: //398/000000000000/SIP/Info/ccsip_call_setup_request: Copy over rediectNumber from call info
Sep 18 07:19:47.588: //398/7B2119E08174/SIP/Info/ccsip_call_setup_request: Copy over rediectNumber from ssInfo
Sep 18 07:19:47.588: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetOutboundHostAndDestHostPrivate: CCSIP: target_host : 10.1.10.1 target_port
: 5060

Sep 18 07:19:47.588: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetOutboundHostAndDestHostPrivate: CCSIP: outbound_host : 10.1.10.1 outbound_p
ort : 5060

Sep 18 07:19:47.588: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_SETUP
Sep 18 07:19:47.588: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_event_handler: 
Sep 18 07:19:47.588: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_event_handler: switch(ev.ev_id: 157)
Sep 18 07:19:47.588: //397/F3BC29C09A29/SIP/Info/ccsip_event_handler:
ccsip_event_handler: peer ID 398 chans 0x87EF9408 event 157 flags 0x844001C 0x300 0x601 data 0x87EF9408
Sep 18 07:19:47.808: //398/7B2119E08174/SIP/Info/sipSPI_ipip_free_codec_profile: Codec Profiles Freed
Sep 18 07:19:47.808: //398/7B2119E08174/SIP/Info/sipSPIUfreeOneCCB: Freeing ccb 864972A8
Sep 18 07:19:47.808: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContextFromTable: NO context for key[387]

Maulik Shah Sun, 09/20/2009 - 14:59

Edwin

  sorry for the delayed response on this. The debugs appear to be cut off right when calls go to the voicemail - can you paste this into a text file and add as an attachment to the post.

thx

Maulik Shah Tue, 09/22/2009 - 09:38

I assume the student2 in the Request URI is just replacing the real phone number.

Based on the trace - it does appear that the call does match the CUE voicemail dial peer but do not see any further logs (which is why I thought logs were missing). As a check:

1. can you send me the dial-peer config (dial-peer voice 3008 & 2000).

2. Do you have the below configured:

voice service voip

  allow-connections sip to sip

3. Can you ensure the voice class codec is setup as below:

voice-class codec 1

no codec pref 1 g711ulaw

no codec pref 2 g729r8

codec pref 1 g711alaw

4. Do calls work to IP phones from the SIP Trunk?

edwinkoning Wed, 09/30/2009 - 14:10

1.

dial-peer voice 3008 voip
translation-profile incoming INCOMING_TRANSLATION_PROFILE
max-conn 5
voice-class codec 1
voice-class sip dtmf-relay force rtp-nte
session protocol sipv2
session target ipv4:10.1.10.1
incoming uri to INCOMINGNR
dtmf-relay rtp-nte
no call fallback
ip qos dscp cs5 media
ip qos dscp cs4 signaling
no vad


dial-peer voice 2000 voip
description ** cue voicemail pilot number **
destination-pattern 500
voice-class sip outbound-proxy ipv4:10.1.10.1
session protocol sipv2
session target ipv4:10.1.10.1
dtmf-relay rtp-nte
codec g711ulaw
no vad


2.
yes.

3.
Yes. It is configured that way.

4.
Yes. Phone are using SCCP. Calls over the trunk are working fine. It is calls that are forwarded to the voicemail that fail.

Maulik Shah Wed, 09/30/2009 - 22:11

Changing the phones from SCCP to SIP should not matter.Try one of the below:

1. Your config is missing all the transcoder config - any reason for that? For example:

voice-card 0
dsp services dspfarm

2. Can you confirm if the inbound SIP INVITEs from the trunk have a request URI with a E164 number as below:

Received:
INVITE sip: [email protected]:5060 SIP/2.0

OR with an alphanumeric string that you are translating using the "incoming uri to INCOMINGNR2"?

Received:
INVITE sip:[email protected]:5060 SIP/2.0

If its the latter - can you try using an E164 number and then checking Call Forward to voicemail?

3. Also, can you call forward to voicemail when calling from IP phone to IP phone internally? I assume yes.

edwinkoning Thu, 10/01/2009 - 05:52

Hello Maulik,

File is missing the information indeed. I've included the latest running-config in the attached file.

Incoming INVITEs look like this (this is incoming from [mymobilenr] to +31107630000):

INVITE sip:[email protected]:5060 SIP/2.0
Record-Route:
Via: SIP/2.0/UDP 213.239.5.68;branch=z9hG4bKfdf1.6944c49.0
Via: SIP/2.0/UDP 213.239.5.69;branch=z9hG4bK265E9A312FB
Via: SIP/2.0/UDP  212.4.211.245:5060;x-route-tag="cid:[email protected]";branch=z9hG4bK265E9A312FB
From: ;tag=5C1106F8-25D5
To:
Date: Thu, 01 Oct 2009 12:28:31 GMT
Call-ID: [email protected]
Supported: 100rel,timer,replaces
Min-SE:  1800
Cisco-Guid: 3279624355-2914783710-2780430362-2730347454
User-Agent: Cisco-SIPGateway/IOS-12.x
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO, UPDATE, REGISTER
CSeq: 101 INVITE
Max-Forwards: 68
Timestamp: 1254400111
Contact:
Expires: 180
Allow-Events: telephone-event
Content-Type: application/sdp
Content-Length: 271
To-Hint: sip:[email protected]
From-Hint: sip:+31[mymobilenr]@test.winitu.com
P-hint: usrloc applied
Remote-Party-ID: ;party=calling;screen=yes

v=0
o=CiscoSystemsSIP-GW-UserAgent 1918 8990 IN IP4 212.4.211.245
s=SIP Call
c=IN IP4 212.4.211.245
t=0 0
m=audio 18734 RTP/AVP 8 101
c=IN IP4 212.4.211.245
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=direction:passive

If I call from one phone to another, everything works fine. If I put one of the phones in forward to 500 (voicemail), the 'internal' call will end up in the voicemail. External calls incoming from the SIP trunk to a phone that has forward to voicemail fail.

Regards,

/Edwin

Maulik Shah Thu, 10/01/2009 - 22:11

Thanks for the new config - that looks much better :)

Can you try the below:

1. Remove the below CLI:

dial-peer voice 3008 voip

  no incoming uri to INCOMINGNR

2. Add g711ulaw to Xcode list

dspfarm profile 1 transcode

  codec g711ulaw

NOTE: you may need to shut the dspfarm profile first, then add the codec and do a no shut

3. Try a test call from the SIP trunk that call forwards to VM - if calls still fail gather:

deb ccsip mess

deb voip ccapi inout

deb ephone mtp

deb dspfarm events

deb dspfarm errors

edwinkoning Sat, 10/03/2009 - 07:08

Maulik,

I've made the changes, and did the call (that unfortunately still fails). I cannot enter the last two debug commands you've given (deb dspfarm ...). In the attachments the updated config, 'sh ver' and calltrace.

/Edwin

Maulik Shah Mon, 10/05/2009 - 09:28

Edwin

  The reason for the failure is there is no DID mapping setup after you removed the voice-class - can you please add the below:

dial-peer voice 3008 voip

  incoming called-number 31107630000

    no session target

    default call fallback

!

voice translation-rule 1

rule 1 /^31107630000$/ /201/

rule 2 /^.*/ /201/

The right debugs are:

deb ccsip mess

deb voip ccapi inout

deb ephone mtp

deb sccp events

deb sccp message

edwinkoning Tue, 10/27/2009 - 07:02

Hello Maulik,

I've updated the config (see included file: UC520_20091027_shrun.docx, UC520_20091027_shver.docx) and done some testing. The UC does react strange though.

To explain:

- I've registered a phone with extension 201 (cisco 7970) that receives the call for 31107630000. The phone has a "CFwdAll" to extension 500 (the voicemail on CUE).

- I call with my mobile phone to the 31107630000 number (hoping to end up in the voicemail of course). Unfortunately, this does not happen.

- When you examine the callflow (see included file: UC520_20091027_debugforwarding, using the deb commands you suggested) you will see that the call is indeed forwarded. Also transcoding takes place.

- The most interesting part however is the external trace on our own platform:
- packet 6 shows the 180 RINGING coming from the UC520 (85.223.63.163).
- This 180 RINGING contains Require:100rel and RSeq fields, asking for a reliable response (according to RFC3262:4 UAC behaviour)
- The 180 RINGING traverses our SIP proxy/loadbalancer and gets answered by the PSTN gateway (a cisco router, .245).
- The router has to respond with a PRACK (RFC3262:3 UAS behaviour: "The UAS MUST send any non-100 provisional response reliably if the initial request contained a Require header field with the option tag 100rel."), which it does.
- The PRACK is sent to [email protected] (the 'internal voicemail number on the UC520), based on the contents of contact-field in the initial 180 RINGING.
- Our SIP platform receives the PRACK and replies with 404, because the number [email protected] does not make any sense..
- After that the session is cancelled in all directions.

My conclusion is that the UC520 asks for a provisional response but uses an 'internal' SIP uri on the external SIP trunk. This behaviour is incorrect (bug?).

Regards,
/Edwin

Maulik Shah Wed, 10/28/2009 - 10:52

Not sure if I would call this a bug - here are your options:

1. Disable PRACK request

voice service voip

  sip

    rel1xx disable

2. Force Contact header to always be a specific number (need UC500 software pack 7.0.x or higher) - below is an example

voice class sip-profiles 1

response ANY sip-header Contact modify "

!

voice service voip

  sip

  sip-profiles 1

More info on SIP profiles is at:

http://www.cisco.com/en/US/products/sw/voicesw/ps5640/products_configuration_example09186a0080982499.shtml

Try the above and see if it works for you.

A_Khabrov Tue, 09/29/2009 - 04:25

Try to add next lines to the config, for correctly connection Transcoder:

telephony-service

max-ephones 1

max-dn 1

Actions

This Discussion

Related Content