[Freeswitch-users] Codec Negotiation Error Lync/UCMA -> external provider

Tue May 21 20:11:31 MSD 2013

Hi there, I'm a newbee, but I've been reading everything I can and I can't
find anything that assists with this.

I have a UCMA app that is internal that communicates on the internal sip
port (set to 5042) and it bridges with dialplan to the external sip trunk
(trying 2, one of which is siproutes).

If I enable proxy, the call rings out and I get dead air on the other side,
but it won't ever properly establish the call in the UCMA app because of
some issue with codecs from what I can tell.

Obviously I don't want to use proxy mode, what I really want to do is use it
straight up and have FS do the transcoding etc.

The problem is that once I do this I get a Codec Negotiation error and I
can't figure out why. Anyone have any ideas as to why it's freaking out like
this? (log below)  Thanks!

2013-05-21 12:09:41.570884 [DEBUG] sofia_glue.c:1219 Local SDP:
v=0
o=FreeSWITCH 1369129003 1369129004 IN IP4 10.8.0.158
s=FreeSWITCH
c=IN IP4 10.8.0.158
t=0 0
m=audio 23578 RTP/AVP 9 0 8 101 13
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

2013-05-21 12:09:41.570884 [DEBUG] mod_sofia.c:114
(sofia/external/+16032897972) State Change CS_INIT -> CS_ROUTING
2013-05-21 12:09:41.570884 [DEBUG] switch_core_session.c:1340 Send signal
sofia/external/+16032897972 [BREAK]
2013-05-21 12:09:41.570884 [DEBUG] switch_core_state_machine.c:454
(sofia/external/+16032897972) State INIT going to sleep
2013-05-21 12:09:41.570884 [DEBUG] switch_core_state_machine.c:415
(sofia/external/+16032897972) Running State Change CS_ROUTING
2013-05-21 12:09:41.570884 [DEBUG] switch_core_state_machine.c:470
(sofia/external/+16032897972) State ROUTING
2013-05-21 12:09:41.570884 [DEBUG] mod_sofia.c:137
sofia/external/+16032897972 SOFIA ROUTING
2013-05-21 12:09:41.570884 [DEBUG] switch_ivr_originate.c:67
(sofia/external/+16032897972) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2013-05-21 12:09:41.570884 [DEBUG] switch_core_session.c:1340 Send signal
sofia/external/+16032897972 [BREAK]
2013-05-21 12:09:41.570884 [DEBUG] switch_core_state_machine.c:470
(sofia/external/+16032897972) State ROUTING going to sleep
2013-05-21 12:09:41.570884 [DEBUG] switch_core_state_machine.c:415
(sofia/external/+16032897972) Running State Change CS_CONSUME_MEDIA
2013-05-21 12:09:41.570884 [DEBUG] switch_core_state_machine.c:489
(sofia/external/+16032897972) State CONSUME_MEDIA
2013-05-21 12:09:41.570884 [DEBUG] switch_core_state_machine.c:489
(sofia/external/+16032897972) State CONSUME_MEDIA going to sleep
2013-05-21 12:09:41.570884 [DEBUG] switch_core_session.c:1005 Send signal
sofia/external/+16032897972 [BREAK]
2013-05-21 12:09:41.570884 [DEBUG] sofia.c:5742 Channel
sofia/external/+16032897972 entering state [calling][0]
2013-05-21 12:09:43.891308 [DEBUG] switch_core_session.c:1005 Send signal
sofia/external/+16032897972 [BREAK]
2013-05-21 12:09:43.891308 [DEBUG] switch_core_session.c:1005 Send signal
sofia/external/+16032897972 [BREAK]
2013-05-21 12:09:43.891308 [INFO] sofia.c:966 sofia/external/+16032897972
Update Callee ID to "+16032897972" <sip:+16032897972 at 4.30.136.195>
2013-05-21 12:09:43.891308 [DEBUG] sofia.c:5742 Channel
sofia/external/+16032897972 entering state [proceeding][183]
2013-05-21 12:09:43.891308 [DEBUG] sofia.c:5751 Remote SDP:
v=0
o=Sonus_UAC 10608 14579 IN IP4 207.239.33.59
s=SIP Media Capabilities
c=IN IP4 207.239.33.59
t=0 0
m=audio 10460 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=maxptime:20

2013-05-21 12:09:43.891308 [DEBUG] switch_core_media.c:2714 Audio Codec
Compare [PCMU:0:8000:20:64000]/[G722:9:8000:20:64000]
2013-05-21 12:09:43.891308 [DEBUG] switch_core_media.c:2714 Audio Codec
Compare [PCMU:0:8000:20:64000]/[PCMU:0:8000:20:64000]
2013-05-21 12:09:43.891308 [DEBUG] switch_core_media.c:1813 Set Codec
sofia/external/+16032897972 PCMU/8000 20 ms 160 samples 64000 bits
2013-05-21 12:09:43.891308 [DEBUG] switch_core_codec.c:111
sofia/external/+16032897972 Original read codec set to PCMU:0
2013-05-21 12:09:43.891308 [DEBUG] switch_core_media.c:2876 Set 2833 dtmf
send payload to 101
2013-05-21 12:09:43.891308 [DEBUG] switch_core_media.c:3800 AUDIO RTP
[sofia/external/+16032897972] 10.8.0.158 port 23578 -> 207.239.33.59 port
10460 codec: 0 m
s: 20
2013-05-21 12:09:43.891308 [DEBUG] switch_rtp.c:2659 Starting timer [soft]
160 bytes per 20ms
2013-05-21 12:09:43.891308 [DEBUG] switch_rtp.c:1231  [   zrtp main]: START
SESSION INITIALIZATION. sID=4.
2013-05-21 12:09:43.891308 [DEBUG] switch_rtp.c:1231  [   zrtp main]:
ZID=306130383030396530393363.
2013-05-21 12:09:43.891308 [DEBUG] switch_rtp.c:1231  [   zrtp main]:
Loading User's profile:
2013-05-21 12:09:43.891308 [DEBUG] switch_rtp.c:1231  [   zrtp main]:   
allowclear: OFF
2013-05-21 12:09:43.891308 [DEBUG] switch_rtp.c:1231  [   zrtp main]:   
autosecure: ON
2013-05-21 12:09:43.891308 [DEBUG] switch_rtp.c:1231  [   zrtp main]: 
disclose_bit: OFF
2013-05-21 12:09:43.891308 [DEBUG] switch_rtp.c:1231  [   zrtp main]: 
signal. role: Initiator
2013-05-21 12:09:43.891308 [DEBUG] switch_rtp.c:1231  [   zrtp main]:          
TTL: 4294967295
2013-05-21 12:09:43.891308 [DEBUG] switch_rtp.c:1231  [   zrtp main]:   SAS
schemes: 2013-05-21 12:09:43.891308 [DEBUG] switch_rtp.c:1231 B256
2013-05-21 12:09:
43.891308 [DEBUG] switch_rtp.c:1231 B32  2013-05-21 12:09:43.891308 [DEBUG]
switch_rtp.c:1231
2013-05-21 12:09:43.891308 [DEBUG] switch_rtp.c:1231  [   zrtp main]:     
Ciphers: 2013-05-21 12:09:43.891308 [DEBUG] switch_rtp.c:1231 AES3
2013-05-21 12:09:4
3.891308 [DEBUG] switch_rtp.c:1231 AES1 2013-05-21 12:09:43.891308 [DEBUG]
switch_rtp.c:1231
2013-05-21 12:09:43.891308 [DEBUG] switch_rtp.c:1231  [   zrtp main]:    PK
schemes: 2013-05-21 12:09:43.891308 [DEBUG] switch_rtp.c:1231 EC25
2013-05-21 12:09:
43.891308 [DEBUG] switch_rtp.c:1231 DH3k 2013-05-21 12:09:43.891308 [DEBUG]
switch_rtp.c:1231 DH2k 2013-05-21 12:09:43.891308 [DEBUG] switch_rtp.c:1231
Mult 201
3-05-21 12:09:43.891308 [DEBUG] switch_rtp.c:1231
2013-05-21 12:09:43.891308 [DEBUG] switch_rtp.c:1231  [   zrtp main]:          
ATL: 2013-05-21 12:09:43.891308 [DEBUG] switch_rtp.c:1231 HS32 2013-05-21
12:09:
43.891308 [DEBUG] switch_rtp.c:1231
2013-05-21 12:09:43.891308 [DEBUG] switch_rtp.c:1231  [   zrtp main]:      
Hashes: 2013-05-21 12:09:43.891308 [DEBUG] switch_rtp.c:1231 S256 2013-05-21
12:09:4
3.891308 [DEBUG] switch_rtp.c:1231
2013-05-21 12:09:43.891308 [DEBUG] switch_rtp.c:1231  [   zrtp main]:
Session initialization - DONE. sID=4.

2013-05-21 12:09:43.891308 [DEBUG] switch_rtp.c:1231  [   zrtp main]: ATTACH
NEW STREAM to sID=4:
2013-05-21 12:09:43.891308 [DEBUG] switch_rtp.c:1231  [        zrtp]:  
Stream ID=0 UNKNOWN switching <NONE> ---> <ACTIVE>.
2013-05-21 12:09:43.891308 [DEBUG] switch_rtp.c:1231  [   zrtp main]:  
Empty slot was found - initializing new stream with ID=4.
2013-05-21 12:09:43.891308 [DEBUG] switch_rtp.c:1231  [   zrtp main]:  
Preparing ZRTP Hello according to the Session profile.
2013-05-21 12:09:43.891308 [DEBUG] switch_rtp.c:1231  [   zrtp main]: ATTACH
NEW STREAM - DONE.
2013-05-21 12:09:43.891308 [DEBUG] switch_rtp.c:1231  [ zrtp engine]: START
STREAM ID=4 mode=CLEAR state=ACTIVE.
2013-05-21 12:09:43.891308 [DEBUG] switch_rtp.c:1231  [        zrtp]:  
Stream ID=4 CLEAR switching <ACTIVE> ---> <START>.
2013-05-21 12:09:43.891308 [DEBUG] switch_rtp.c:1231  [  zrtp utils]:   Send
<HELLO> ssrc=1428962591 seq=54611 size=144. Stream 4:CLEAR:START
2013-05-21 12:09:43.891308 [DEBUG] switch_core_media.c:4145 Set 2833 dtmf
send payload to 101
2013-05-21 12:09:43.891308 [DEBUG] switch_core_media.c:4151 Set 2833 dtmf
receive payload to 101
2013-05-21 12:09:43.891308 [NOTICE] sofia_media.c:92 Pre-Answer
sofia/external/+16032897972!
2013-05-21 12:09:43.891308 [DEBUG] switch_channel.c:3273 Send signal
sofia/internal/+16032897972 at 173.255.174.20 [BREAK]
2013-05-21 12:09:43.891308 [DEBUG] switch_channel.c:3277
(sofia/external/+16032897972) Callstate Change DOWN -> EARLY
2013-05-21 12:09:43.911297 [DEBUG] switch_ivr_originate.c:411 Setting codec
string on sofia/internal/+16032897972 at 173.255.174.20 to PCMU at 8000h@20i
2013-05-21 12:09:43.911297 [INFO] switch_ivr_originate.c:3416 Sending early
media
2013-05-21 12:09:43.911297 [ERR] switch_core_media.c:2549 a=crypto in
RTP/AVP, refer to rfc3711
2013-05-21 12:09:43.911297 [ERR] mod_sofia.c:2081 CODEC NEGOTIATION ERROR. 
SDP:
v=0
o=- 1 0 IN IP4 10.8.0.158
s=session
c=IN IP4 10.8.0.158
b=CT:10000
t=0 0
m=audio 2908 RTP/AVP 9 112 111 0 8 116 13 118 97 101
c=IN IP4 10.8.0.158
a=rtpmap:9 G722/8000
a=rtpmap:112 G7221/16000
a=fmtp:112 bitrate=24000
a=rtpmap:111 SIREN/16000
a=fmtp:111 bitrate=16000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:116 AAL2-G726-32/8000
a=rtpmap:13 CN/8000
a=rtpmap:118 CN/16000
a=rtpmap:97 RED/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16,36
a=rtcp:2909
a=label:main-audio
a=crypto:1 AES_CM_128_HMAC_SHA1_80
inline:BqtEfRv/sMasd3GS0I4FJRX5hh7BKVt+r8/vKbOk

--
View this message in context: http://freeswitch-users.2379917.n2.nabble.com/Codec-Negotiation-Error-Lync-UCMA-external-provider-tp7590911.html
Sent from the freeswitch-users mailing list archive at Nabble.com.