Re: [Freeswitch-users] Error in codec negotiation: What are all the places that specify accepted codecs for outgoing calls?
Thanks for the help. I'm working on a clean log. We had many outgoing calls at the same time, the console log is mixed up with other calls. Digging more into our logs, it seems the issue is sporadic: 50% of the time we can connect to a switch offering only PCMA, and other times we only offer PCMU and get this codec negotiation error. The configuration has not changed across calls:
<X-PRE-PROCESS cmd="set" data="global_codec_prefs=G722,PCMU,PCMA,GSM"/> <X-PRE-PROCESS cmd="set" data="outbound_codec_prefs=PCMU,PCMA,GSM"/>
I'll work on a console log and sip trace. In the meantime, any idea what could cause variation between calls in the codecs offered? +Mark
From: Kristian Kielhofner <kris@kriskinc.com> Subject: Re: [Freeswitch-users] Error in codec negotiation: What are all the places that specify accepted codecs for outgoing calls? Date: 6 June 2014 18:17:47 GMT To: FreeSWITCH Users Help <freeswitch-users@lists.freeswitch.org> Reply-To: FreeSWITCH Users Help <freeswitch-users@lists.freeswitch.org>
We would need to see a full siptrace and console log to see what's happening here.
On Fri, Jun 6, 2014 at 10:27 AM, Mark Boots <mark@votomobile.org> wrote:
We're using a major VoIP terminator and finding that on many outgoing calls, Freeswitch hangs up with INCOMPATIBLE_DESTINATION after trying to negotiate codecs.
The carrier offers PCMA, and it looks like Freeswitch refuses to accept anything but PCMU:
2014-06-06 13:18:54.115197 [NOTICE] sofia_media.c:92 Pre-Answer sofia/external/0011104555493618652! 2014-06-06 13:18:54.115197 [DEBUG] switch_channel.c:3277 (sofia/external/0011104555493618652) Callstate Change DOWN -> EARLY 2014-06-06 13:18:54.175210 [DEBUG] switch_core_session.c:1005 Send signal sofia/external/0011104555391494140 [BREAK] 2014-06-06 13:18:54.175210 [DEBUG] switch_core_session.c:1005 Send signal sofia/external/0011104555391494140 [BREAK] 2014-06-06 13:18:54.175210 [DEBUG] sofia.c:5741 Channel sofia/external/0011104555391494140 entering state [proceeding][183] 2014-06-06 13:18:54.175210 [DEBUG] sofia.c:5750 Remote SDP: v=0 o=- 313783328916230866 1 IN IP4 81.52.176.165 s=- c=IN IP4 81.52.176.165 t=0 0 a=sendrecv m=audio 25080 RTP/AVP 8 13 101 a=rtpmap:8 PCMA/8000 a=rtpmap:13 CN/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15
2014-06-06 13:18:54.175210 [DEBUG] switch_core_media.c:2585 Set comfort noise payload to 13 2014-06-06 13:18:54.175210 [DEBUG] switch_core_media.c:2662 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMU:0:8000:20:64000] 2014-06-06 13:18:54.175210 [DEBUG] switch_core_media.c:2662 Audio Codec Compare [CN:13:8000:20:0]/[PCMU:0:8000:20:64000] 2014-06-06 13:18:54.175210 [DEBUG] switch_core_media.c:2662 Audio Codec Compare [telephone-event:101:8000:20:0]/[PCMU:0:8000:20:64000] 2014-06-06 13:18:54.175210 [DEBUG] switch_core_media.c:2824 Set 2833 dtmf send payload to 101 2014-06-06 13:18:54.175210 [DEBUG] switch_core_session.c:1005 Send signal sofia/external/0011104555391494140 [BREAK] 2014-06-06 13:18:54.175210 [NOTICE] sofia.c:5868 Hangup sofia/external/0011104555391494140 [CS_CONSUME_MEDIA] [INCOMPATIBLE_DESTINATION]
However, our codec settings in vars.xml specify:
<X-PRE-PROCESS cmd="set" data="global_codec_prefs=G722,PCMU,PCMA,GSM"/> <X-PRE-PROCESS cmd="set" data="outbound_codec_prefs=PCMU,PCMA,GSM"/>
The sip profile uses these settings. Any idea how to debug what codecs Freeswitch is willing to accept?
Thanks! +Mark
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
-- Kristian Kielhofner
Hi Kristian, I've narrowed this INCOMPATIBLE_DESTINATION error down to a specific case: 1 - Freeswitch sends the outgoing call, and offers PCMU/PCMA/GSM 2 - Other end accepts only PCMU 3 - At some point after Pre-answer, the other end issues a 183 Session Progress, changing to only accept PCMA. 4 - Freeswitch attempts to select new codecs but only looks at PCMU, and cancels the call with INCOMPATIBLE_DESTINATION. Here is the console log and sip trace... Hope it helps! +Mark 2014-06-09 21:35:39.615207 [DEBUG] switch_ivr_originate.c:2069 Parsing global variables 2014-06-09 21:35:39.615207 [DEBUG] switch_event.c:1661 Parsing variable [plivo_request_uuid]=[004fd8a2-f01e-11e3-844d-22000ad937f0] 2014-06-09 21:35:39.615207 [DEBUG] switch_event.c:1661 Parsing variable [plivo_answer_url]=[http://10.8.0.1/deliverylogs/answer/752471] 2014-06-09 21:35:39.615207 [DEBUG] switch_event.c:1661 Parsing variable [plivo_ring_url]=[http://127.0.0.1/callqueue/ring.php] 2014-06-09 21:35:39.615207 [DEBUG] switch_event.c:1661 Parsing variable [plivo_hangup_url]=[http://127.0.0.1/callqueue/hangup.php] 2014-06-09 21:35:39.615207 [DEBUG] switch_event.c:1661 Parsing variable [origination_caller_id_number]=[12026004299] 2014-06-09 21:35:39.615207 [DEBUG] switch_event.c:1661 Parsing variable [plivo_from]=[12026004299] 2014-06-09 21:35:39.615207 [DEBUG] switch_event.c:1661 Parsing variable [plivo_to]=[0011104555592211972] 2014-06-09 21:35:39.615207 [DEBUG] switch_event.c:1661 Parsing variable [plivo_app]=[true] 2014-06-09 21:35:39.615207 [DEBUG] switch_event.c:1661 Parsing variable [originate_timeout]=[60] 2014-06-09 21:35:39.615207 [DEBUG] switch_event.c:1661 Parsing variable [ignore_early_media]=[true] 2014-06-09 21:35:39.615207 [NOTICE] switch_channel.c:1049 New Channel sofia/external/0011104555592211972 [005052e6-f01e-11e3-bbae-cbf0f4eac998] 2014-06-09 21:35:39.615207 [DEBUG] mod_sofia.c:5237 (sofia/external/0011104555592211972) State Change CS_NEW -> CS_INIT 2014-06-09 21:35:39.615207 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/0011104555592211972 [BREAK] 2014-06-09 21:35:39.615207 [DEBUG] switch_core_state_machine.c:418 (sofia/external/0011104555592211972) Running State Change CS_INIT 2014-06-09 21:35:39.615207 [DEBUG] switch_core_state_machine.c:458 (sofia/external/0011104555592211972) State INIT 2014-06-09 21:35:39.615207 [DEBUG] mod_sofia.c:87 sofia/external/0011104555592211972 SOFIA INIT 2014-06-09 21:35:39.615207 [DEBUG] sofia_glue.c:2746 sofia/external/0011104555592211972 sending invite version: 1.2.24 git 7b74ee3 2014-06-03 00:26:24Z 32bit Local SDP: v=0 o=FreeSWITCH 1402325141 1402325142 IN IP4 54.203.245.50 s=FreeSWITCH c=IN IP4 54.203.245.50 t=0 0 m=audio 24598 RTP/AVP 0 8 3 101 13 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv 2014-06-09 21:35:39.615207 [DEBUG] mod_sofia.c:127 (sofia/external/0011104555592211972) State Change CS_INIT -> CS_ROUTING 2014-06-09 21:35:39.615207 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/0011104555592211972 [BREAK] 2014-06-09 21:35:39.615207 [DEBUG] switch_core_state_machine.c:458 (sofia/external/0011104555592211972) State INIT going to sleep send 1071 bytes to udp/[108.59.2.133]:5060 at 21:35:39.620673: ------------------------------------------------------------------------ INVITE sip:0011104555592211972@108.59.2.133 SIP/2.0 Via: SIP/2.0/UDP 54.203.245.50:5080;rport;branch=z9hG4bKUNeNtZcZp5ZmB Max-Forwards: 70 From: "" <sip:12026004299@54.203.245.50>;tag=9Z1HtD145Qv3K To: <sip:0011104555592211972@108.59.2.133> Call-ID: d7aeb7a1-6ac0-1232-718c-22000ad937f0 CSeq: 60838805 INVITE Contact: <sip:gw+voxbeam_outbound@54.203.245.50:5080;transport=udp;gw=voxbeam_outbound> User-Agent: FreeSWITCH-mod_sofia/1.2.24+git~20140603T002624Z~7b74ee3955~32bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Type: application/sdp Content-Disposition: session Content-Length: 207 X-FS-Support: update_display,send_info Remote-Party-ID: <sip:12026004299@54.203.245.50>;party=calling;screen=yes;privacy=off v=0 o=FreeSWITCH 1402325141 1402325142 IN IP4 54.203.245.50 s=FreeSWITCH c=IN IP4 54.203.245.50 t=0 0 m=audio 24598 RTP/AVP 0 8 3 101 13 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ 2014-06-09 21:35:39.615207 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/0011104555592211972 [BREAK] 2014-06-09 21:35:39.615207 [DEBUG] switch_core_state_machine.c:418 (sofia/external/0011104555592211972) Running State Change CS_ROUTING 2014-06-09 21:35:39.615207 [DEBUG] sofia.c:5845 Channel sofia/external/0011104555592211972 entering state [calling][0] 2014-06-09 21:35:39.615207 [DEBUG] switch_core_state_machine.c:474 (sofia/external/0011104555592211972) State ROUTING 2014-06-09 21:35:39.615207 [DEBUG] mod_sofia.c:150 sofia/external/0011104555592211972 SOFIA ROUTING 2014-06-09 21:35:39.615207 [DEBUG] switch_ivr_originate.c:67 (sofia/external/0011104555592211972) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2014-06-09 21:35:39.615207 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/0011104555592211972 [BREAK] 2014-06-09 21:35:39.615207 [DEBUG] switch_core_state_machine.c:474 (sofia/external/0011104555592211972) State ROUTING going to sleep 2014-06-09 21:35:39.615207 [DEBUG] switch_core_state_machine.c:418 (sofia/external/0011104555592211972) Running State Change CS_CONSUME_MEDIA 2014-06-09 21:35:39.615207 [DEBUG] switch_core_state_machine.c:493 (sofia/external/0011104555592211972) State CONSUME_MEDIA 2014-06-09 21:35:39.615207 [DEBUG] switch_core_state_machine.c:493 (sofia/external/0011104555592211972) State CONSUME_MEDIA going to sleep recv 367 bytes from udp/[108.59.2.133]:5060 at 21:35:39.725204: ------------------------------------------------------------------------ SIP/2.0 100 Giving a try Via: SIP/2.0/UDP 54.203.245.50:5080;received=54.203.245.50;rport=5080;branch=z9hG4bKUNeNtZcZp5ZmB From: "" <sip:12026004299@54.203.245.50>;tag=9Z1HtD145Qv3K To: <sip:0011104555592211972@108.59.2.133> Call-ID: d7aeb7a1-6ac0-1232-718c-22000ad937f0 CSeq: 60838805 INVITE Server: OpenSIPS (1.8.2-notls (x86_64/linux)) Content-Length: 0 ------------------------------------------------------------------------ recv 657 bytes from udp/[108.59.2.133]:5060 at 21:35:41.191275: ------------------------------------------------------------------------ SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 54.203.245.50:5080;rport;branch=z9hG4bKUNeNtZcZp5ZmB From: "" <sip:12026004299@54.203.245.50>;tag=9Z1HtD145Qv3K To: <sip:0011104555592211972@108.59.2.133>;tag=9312047651043624688 Call-ID: d7aeb7a1-6ac0-1232-718c-22000ad937f0 CSeq: 60838805 INVITE Content-Type: application/sdp Contact: <sip:callee@108.59.2.133;did=795.65454242> Supported: timer,100rel Content-Length: 226 v=0 o=RISNEXT02 869 1999 IN IP4 80.84.30.41 s=sip call c=IN IP4 80.84.30.41 t=0 0 m=audio 42108 RTP/AVP 0 13 101 a=rtpmap:0 PCMU/8000 a=rtpmap:13 CN/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ 2014-06-09 21:35:41.175213 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/0011104555592211972 [BREAK] 2014-06-09 21:35:41.175213 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/0011104555592211972 [BREAK] 2014-06-09 21:35:41.175213 [DEBUG] sofia.c:5845 Channel sofia/external/0011104555592211972 entering state [proceeding][183] 2014-06-09 21:35:41.175213 [DEBUG] sofia.c:5858 Remote SDP: v=0 o=RISNEXT02 869 1999 IN IP4 80.84.30.41 s=sip call c=IN IP4 80.84.30.41 t=0 0 m=audio 42108 RTP/AVP 0 13 101 a=rtpmap:0 PCMU/8000 a=rtpmap:13 CN/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 2014-06-09 21:35:41.175213 [DEBUG] sofia_glue.c:5284 Audio Codec Compare [PCMU:0:8000:20:64000]/[PCMU:0:8000:20:64000] 2014-06-09 21:35:41.175213 [DEBUG] sofia_glue.c:3192 Set Codec sofia/external/0011104555592211972 PCMU/8000 20 ms 160 samples 64000 bits 2014-06-09 21:35:41.175213 [DEBUG] switch_core_codec.c:111 sofia/external/0011104555592211972 Original read codec set to PCMU:0 2014-06-09 21:35:41.175213 [DEBUG] sofia_glue.c:5444 Set 2833 dtmf send payload to 101 2014-06-09 21:35:41.175213 [DEBUG] sofia_glue.c:3451 AUDIO RTP [sofia/external/0011104555592211972] 10.217.55.240 port 24598 -> 80.84.30.41 port 42108 codec: 0 ms: 20 2014-06-09 21:35:41.175213 [DEBUG] switch_rtp.c:2040 Starting timer [soft] 160 bytes per 20ms 2014-06-09 21:35:41.175213 [DEBUG] sofia_glue.c:3718 Set 2833 dtmf send payload to 101 2014-06-09 21:35:41.175213 [DEBUG] sofia_glue.c:3724 Set 2833 dtmf receive payload to 101 2014-06-09 21:35:41.175213 [DEBUG] sofia_glue.c:3751 sofia/external/0011104555592211972 Set rtp dtmf delay to 40 2014-06-09 21:35:41.175213 [DEBUG] sofia_glue.c:3757 Set comfort noise payload to 13 2014-06-09 21:35:41.175213 [NOTICE] sofia_glue.c:4362 Pre-Answer sofia/external/0011104555592211972! 2014-06-09 21:35:41.175213 [DEBUG] switch_channel.c:3370 (sofia/external/0011104555592211972) Callstate Change DOWN -> EARLY recv 739 bytes from udp/[108.59.2.133]:5060 at 21:35:49.145080: ------------------------------------------------------------------------ SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 54.203.245.50:5080;rport;branch=z9hG4bKUNeNtZcZp5ZmB From: "" <sip:12026004299@54.203.245.50>;tag=9Z1HtD145Qv3K To: <sip:0011104555592211972@108.59.2.133>;tag=B2B.1560.1531 Call-ID: d7aeb7a1-6ac0-1232-718c-22000ad937f0 CSeq: 60838805 INVITE Content-Type: application/sdp Allow: INVITE,ACK,CANCEL,BYE,OPTIONS,PRACK,UPDATE Contact: <sip:callee@108.59.2.133;did=795.65454242> Server: OpenSIPS (1.6.4-2-notls (x86_64/linux)) Content-Length: 239 v=0 o=- 339363712333429347 1 IN IP4 81.52.176.165 s=- c=IN IP4 81.52.176.165 t=0 0 a=sendrecv m=audio 32736 RTP/AVP 8 13 101 a=rtpmap:8 PCMA/8000 a=rtpmap:13 CN/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv ------------------------------------------------------------------------ 2014-06-09 21:35:49.135201 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/0011104555592211972 [BREAK] 2014-06-09 21:35:49.135201 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/0011104555592211972 [BREAK] 2014-06-09 21:35:49.135201 [DEBUG] sofia.c:5845 Channel sofia/external/0011104555592211972 entering state [proceeding][183] 2014-06-09 21:35:49.135201 [DEBUG] sofia.c:5858 Remote SDP: v=0 o=- 339363712333429347 1 IN IP4 81.52.176.165 s=- c=IN IP4 81.52.176.165 t=0 0 a=sendrecv m=audio 32736 RTP/AVP 8 13 101 a=rtpmap:8 PCMA/8000 a=rtpmap:13 CN/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 2014-06-09 21:35:49.135201 [DEBUG] sofia_glue.c:5284 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMU:0:8000:20:64000] 2014-06-09 21:35:49.135201 [DEBUG] sofia_glue.c:5226 Set comfort noise payload to 13 2014-06-09 21:35:49.135201 [DEBUG] sofia_glue.c:5284 Audio Codec Compare [CN:13:8000:20:0]/[PCMU:0:8000:20:64000] 2014-06-09 21:35:49.135201 [DEBUG] sofia_glue.c:5284 Audio Codec Compare [telephone-event:101:8000:20:0]/[PCMU:0:8000:20:64000] 2014-06-09 21:35:49.135201 [DEBUG] sofia_glue.c:5444 Set 2833 dtmf send payload to 101 2014-06-09 21:35:49.135201 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/0011104555592211972 [BREAK] 2014-06-09 21:35:49.135201 [NOTICE] sofia.c:6012 Hangup sofia/external/0011104555592211972 [CS_CONSUME_MEDIA] [INCOMPATIBLE_DESTINATION] 2014-06-09 21:35:49.135201 [DEBUG] switch_channel.c:3189 Send signal sofia/external/0011104555592211972 [KILL] 2014-06-09 21:35:49.135201 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/0011104555592211972 [BREAK] 2014-06-09 21:35:49.135201 [DEBUG] sofia.c:1109 Channel is already hungup. 2014-06-09 21:35:49.135201 [DEBUG] switch_core_state_machine.c:418 (sofia/external/0011104555592211972) Running State Change CS_HANGUP 2014-06-09 21:35:49.135201 [DEBUG] switch_core_state_machine.c:681 (sofia/external/0011104555592211972) Callstate Change EARLY -> HANGUP 2014-06-09 21:35:49.135201 [DEBUG] switch_core_state_machine.c:683 (sofia/external/0011104555592211972) State HANGUP 2014-06-09 21:35:49.135201 [DEBUG] mod_sofia.c:506 Channel sofia/external/0011104555592211972 hanging up, cause: INCOMPATIBLE_DESTINATION 2014-06-09 21:35:49.135201 [DEBUG] mod_sofia.c:568 Sending CANCEL to sofia/external/0011104555592211972 2014-06-09 21:35:49.135201 [DEBUG] switch_core_state_machine.c:48 sofia/external/0011104555592211972 Standard HANGUP, cause: INCOMPATIBLE_DESTINATION 2014-06-09 21:35:49.135201 [DEBUG] switch_core_state_machine.c:683 (sofia/external/0011104555592211972) State HANGUP going to sleep 2014-06-09 21:35:49.135201 [DEBUG] switch_core_state_machine.c:450 (sofia/external/0011104555592211972) State Change CS_HANGUP -> CS_REPORTING 2014-06-09 21:35:49.135201 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/0011104555592211972 [BREAK] 2014-06-09 21:35:49.135201 [DEBUG] switch_core_state_machine.c:418 (sofia/external/0011104555592211972) Running State Change CS_REPORTING send 393 bytes to udp/[108.59.2.133]:5060 at 21:35:49.147250: ------------------------------------------------------------------------ CANCEL sip:0011104555592211972@108.59.2.133 SIP/2.0 Via: SIP/2.0/UDP 54.203.245.50:5080;rport;branch=z9hG4bKUNeNtZcZp5ZmB Max-Forwards: 70 From: "" <sip:12026004299@54.203.245.50>;tag=9Z1HtD145Qv3K To: <sip:0011104555592211972@108.59.2.133> Call-ID: d7aeb7a1-6ac0-1232-718c-22000ad937f0 CSeq: 60838805 CANCEL Reason: Q.850;cause=88;text="INCOMPATIBLE_DESTINATION" Content-Length: 0 ------------------------------------------------------------------------ 2014-06-09 21:35:49.135201 [DEBUG] switch_core_state_machine.c:767 (sofia/external/0011104555592211972) State REPORTING 2014-06-09 21:35:49.135201 [DEBUG] switch_core_state_machine.c:92 sofia/external/0011104555592211972 Standard REPORTING, cause: INCOMPATIBLE_DESTINATION 2014-06-09 21:35:49.135201 [DEBUG] switch_core_state_machine.c:767 (sofia/external/0011104555592211972) State REPORTING going to sleep 2014-06-09 21:35:49.135201 [DEBUG] switch_core_state_machine.c:444 (sofia/external/0011104555592211972) State Change CS_REPORTING -> CS_DESTROY 2014-06-09 21:35:49.135201 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/0011104555592211972 [BREAK] 2014-06-09 21:35:49.135201 [DEBUG] switch_core_session.c:1559 Session 11651 (sofia/external/0011104555592211972) Locked, Waiting on external entities 2014-06-09 21:35:49.135201 [DEBUG] switch_ivr_originate.c:3656 Originate Resulted in Error Cause: 88 [INCOMPATIBLE_DESTINATION] 2014-06-09 21:35:49.135201 [NOTICE] switch_core_session.c:1577 Session 11651 (sofia/external/0011104555592211972) Ended 2014-06-09 21:35:49.135201 [NOTICE] switch_core_session.c:1581 Close Channel sofia/external/0011104555592211972 [CS_DESTROY] 2014-06-09 21:35:49.135201 [DEBUG] switch_core_state_machine.c:572 (sofia/external/0011104555592211972) Running State Change CS_DESTROY 2014-06-09 21:35:49.135201 [DEBUG] switch_core_state_machine.c:582 (sofia/external/0011104555592211972) State DESTROY 2014-06-09 21:35:49.135201 [DEBUG] mod_sofia.c:399 sofia/external/0011104555592211972 SOFIA DESTROY 2014-06-09 21:35:49.155267 [DEBUG] switch_core_state_machine.c:99 sofia/external/0011104555592211972 Standard DESTROY 2014-06-09 21:35:49.155267 [DEBUG] switch_core_state_machine.c:582 (sofia/external/0011104555592211972) State DESTROY going to sleep recv 406 bytes from udp/[108.59.2.133]:5060 at 21:35:49.251931: ------------------------------------------------------------------------ SIP/2.0 200 canceling Via: SIP/2.0/UDP 54.203.245.50:5080;received=54.203.245.50;rport=5080;branch=z9hG4bKUNeNtZcZp5ZmB From: "" <sip:12026004299@54.203.245.50>;tag=9Z1HtD145Qv3K To: <sip:0011104555592211972@108.59.2.133>;tag=ae7a8cec11372a827e55d7147ba55fe7-880b Call-ID: d7aeb7a1-6ac0-1232-718c-22000ad937f0 CSeq: 60838805 CANCEL Server: OpenSIPS (1.8.2-notls (x86_64/linux)) Content-Length: 0 ------------------------------------------------------------------------ recv 386 bytes from udp/[108.59.2.133]:5060 at 21:35:49.426167: ------------------------------------------------------------------------ SIP/2.0 487 Request cancelled Via: SIP/2.0/UDP 54.203.245.50:5080;rport;branch=z9hG4bKUNeNtZcZp5ZmB From: "" <sip:12026004299@54.203.245.50>;tag=9Z1HtD145Qv3K To: <sip:0011104555592211972@108.59.2.133>;tag=2283ef55d8cd9f773784ed9616b0f414-886b Call-ID: d7aeb7a1-6ac0-1232-718c-22000ad937f0 CSeq: 60838805 INVITE Server: OpenSIPS (1.7.1-notls (x86_64/linux)) Content-Length: 0 ------------------------------------------------------------------------ send 373 bytes to udp/[108.59.2.133]:5060 at 21:35:49.426398: ------------------------------------------------------------------------ ACK sip:0011104555592211972@108.59.2.133 SIP/2.0 Via: SIP/2.0/UDP 54.203.245.50:5080;rport;branch=z9hG4bKUNeNtZcZp5ZmB Max-Forwards: 70 From: "" <sip:12026004299@54.203.245.50>;tag=9Z1HtD145Qv3K To: <sip:0011104555592211972@108.59.2.133>;tag=2283ef55d8cd9f773784ed9616b0f414-886b Call-ID: d7aeb7a1-6ac0-1232-718c-22000ad937f0 CSeq: 60838805 ACK Content-Length: 0 ------------------------------------------------------------------------ On 7 Jun 2014, at 15:39, Mark Boots <mark@votomobile.org> wrote:
Thanks for the help. I'm working on a clean log. We had many outgoing calls at the same time, the console log is mixed up with other calls.
Digging more into our logs, it seems the issue is sporadic: 50% of the time we can connect to a switch offering only PCMA, and other times we only offer PCMU and get this codec negotiation error. The configuration has not changed across calls:
<X-PRE-PROCESS cmd="set" data="global_codec_prefs=G722,PCMU,PCMA,GSM"/> <X-PRE-PROCESS cmd="set" data="outbound_codec_prefs=PCMU,PCMA,GSM"/>
I'll work on a console log and sip trace. In the meantime, any idea what could cause variation between calls in the codecs offered?
+Mark
From: Kristian Kielhofner <kris@kriskinc.com> Subject: Re: [Freeswitch-users] Error in codec negotiation: What are all the places that specify accepted codecs for outgoing calls? Date: 6 June 2014 18:17:47 GMT To: FreeSWITCH Users Help <freeswitch-users@lists.freeswitch.org> Reply-To: FreeSWITCH Users Help <freeswitch-users@lists.freeswitch.org>
We would need to see a full siptrace and console log to see what's happening here.
On Fri, Jun 6, 2014 at 10:27 AM, Mark Boots <mark@votomobile.org> wrote:
We're using a major VoIP terminator and finding that on many outgoing calls, Freeswitch hangs up with INCOMPATIBLE_DESTINATION after trying to negotiate codecs.
The carrier offers PCMA, and it looks like Freeswitch refuses to accept anything but PCMU:
2014-06-06 13:18:54.115197 [NOTICE] sofia_media.c:92 Pre-Answer sofia/external/0011104555493618652! 2014-06-06 13:18:54.115197 [DEBUG] switch_channel.c:3277 (sofia/external/0011104555493618652) Callstate Change DOWN -> EARLY 2014-06-06 13:18:54.175210 [DEBUG] switch_core_session.c:1005 Send signal sofia/external/0011104555391494140 [BREAK] 2014-06-06 13:18:54.175210 [DEBUG] switch_core_session.c:1005 Send signal sofia/external/0011104555391494140 [BREAK] 2014-06-06 13:18:54.175210 [DEBUG] sofia.c:5741 Channel sofia/external/0011104555391494140 entering state [proceeding][183] 2014-06-06 13:18:54.175210 [DEBUG] sofia.c:5750 Remote SDP: v=0 o=- 313783328916230866 1 IN IP4 81.52.176.165 s=- c=IN IP4 81.52.176.165 t=0 0 a=sendrecv m=audio 25080 RTP/AVP 8 13 101 a=rtpmap:8 PCMA/8000 a=rtpmap:13 CN/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15
2014-06-06 13:18:54.175210 [DEBUG] switch_core_media.c:2585 Set comfort noise payload to 13 2014-06-06 13:18:54.175210 [DEBUG] switch_core_media.c:2662 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMU:0:8000:20:64000] 2014-06-06 13:18:54.175210 [DEBUG] switch_core_media.c:2662 Audio Codec Compare [CN:13:8000:20:0]/[PCMU:0:8000:20:64000] 2014-06-06 13:18:54.175210 [DEBUG] switch_core_media.c:2662 Audio Codec Compare [telephone-event:101:8000:20:0]/[PCMU:0:8000:20:64000] 2014-06-06 13:18:54.175210 [DEBUG] switch_core_media.c:2824 Set 2833 dtmf send payload to 101 2014-06-06 13:18:54.175210 [DEBUG] switch_core_session.c:1005 Send signal sofia/external/0011104555391494140 [BREAK] 2014-06-06 13:18:54.175210 [NOTICE] sofia.c:5868 Hangup sofia/external/0011104555391494140 [CS_CONSUME_MEDIA] [INCOMPATIBLE_DESTINATION]
However, our codec settings in vars.xml specify:
<X-PRE-PROCESS cmd="set" data="global_codec_prefs=G722,PCMU,PCMA,GSM"/> <X-PRE-PROCESS cmd="set" data="outbound_codec_prefs=PCMU,PCMA,GSM"/>
The sip profile uses these settings. Any idea how to debug what codecs Freeswitch is willing to accept?
Thanks! +Mark
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
-- Kristian Kielhofner
Hi Mark, Thanks for providing the full log. While goofy this is perfectly valid behavior. Because your instance of Freeswitch offers pcma and pcmu it's ok for the other side to switch between the two in 183. A few things to try: - Limit your outbound offers to pcma or pcmu only (one codec). - The remote side appears to support 100rel (PRACK). Try enabling it in Freeswitch. While a long shot it's possible that PRACK'ing the initial received 183 might change the codec swap behavior of the remote end. - Try Freeswitch 1.4 or master. There's been some significant changes in media/SDP behavior, particularly when the remote end does technically standards compliant but goofy things with multiple codec offers. If none of these works you're only option may be to have the carrier take some action. On Monday, June 9, 2014, Mark Boots <mark@votomobile.org> wrote:
Hi Kristian,
I've narrowed this INCOMPATIBLE_DESTINATION error down to a specific case:
1 - Freeswitch sends the outgoing call, and offers PCMU/PCMA/GSM 2 - Other end accepts only PCMU 3 - At some point after Pre-answer, the other end issues a 183 Session Progress, changing to only accept PCMA. 4 - Freeswitch attempts to select new codecs but only looks at PCMU, and cancels the call with INCOMPATIBLE_DESTINATION.
Here is the console log and sip trace... Hope it helps!
+Mark
2014-06-09 21:35:39.615207 [DEBUG] switch_ivr_originate.c:2069 Parsing global variables 2014-06-09 21:35:39.615207 [DEBUG] switch_event.c:1661 Parsing variable [plivo_request_uuid]=[004fd8a2-f01e-11e3-844d-22000ad937f0] 2014-06-09 21:35:39.615207 [DEBUG] switch_event.c:1661 Parsing variable [plivo_answer_url]=[http://10.8.0.1/deliverylogs/answer/752471] 2014-06-09 21:35:39.615207 [DEBUG] switch_event.c:1661 Parsing variable [plivo_ring_url]=[http://127.0.0.1/callqueue/ring.php] 2014-06-09 21:35:39.615207 [DEBUG] switch_event.c:1661 Parsing variable [plivo_hangup_url]=[http://127.0.0.1/callqueue/hangup.php] 2014-06-09 21:35:39.615207 [DEBUG] switch_event.c:1661 Parsing variable [origination_caller_id_number]=[12026004299] 2014-06-09 21:35:39.615207 [DEBUG] switch_event.c:1661 Parsing variable [plivo_from]=[12026004299] 2014-06-09 21:35:39.615207 [DEBUG] switch_event.c:1661 Parsing variable [plivo_to]=[0011104555592211972] 2014-06-09 21:35:39.615207 [DEBUG] switch_event.c:1661 Parsing variable [plivo_app]=[true] 2014-06-09 21:35:39.615207 [DEBUG] switch_event.c:1661 Parsing variable [originate_timeout]=[60] 2014-06-09 21:35:39.615207 [DEBUG] switch_event.c:1661 Parsing variable [ignore_early_media]=[true] 2014-06-09 21:35:39.615207 [NOTICE] switch_channel.c:1049 New Channel sofia/external/0011104555592211972 [005052e6-f01e-11e3-bbae-cbf0f4eac998] 2014-06-09 21:35:39.615207 [DEBUG] mod_sofia.c:5237 (sofia/external/0011104555592211972) State Change CS_NEW -> CS_INIT 2014-06-09 21:35:39.615207 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/0011104555592211972 [BREAK] 2014-06-09 21:35:39.615207 [DEBUG] switch_core_state_machine.c:418 (sofia/external/0011104555592211972) Running State Change CS_INIT 2014-06-09 21:35:39.615207 [DEBUG] switch_core_state_machine.c:458 (sofia/external/0011104555592211972) State INIT 2014-06-09 21:35:39.615207 [DEBUG] mod_sofia.c:87 sofia/external/0011104555592211972 SOFIA INIT 2014-06-09 21:35:39.615207 [DEBUG] sofia_glue.c:2746 sofia/external/0011104555592211972 sending invite version: 1.2.24 git 7b74ee3 2014-06-03 00:26:24Z 32bit Local SDP: v=0 o=FreeSWITCH 1402325141 1402325142 IN IP4 54.203.245.50 s=FreeSWITCH c=IN IP4 54.203.245.50 t=0 0 m=audio 24598 RTP/AVP 0 8 3 101 13 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv
2014-06-09 21:35:39.615207 [DEBUG] mod_sofia.c:127 (sofia/external/0011104555592211972) State Change CS_INIT -> CS_ROUTING 2014-06-09 21:35:39.615207 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/0011104555592211972 [BREAK] 2014-06-09 21:35:39.615207 [DEBUG] switch_core_state_machine.c:458 (sofia/external/0011104555592211972) State INIT going to sleep send 1071 bytes to udp/[108.59.2.133]:5060 at 21:35:39.620673: ------------------------------------------------------------------------ INVITE sip:0011104555592211972@108.59.2.133 SIP/2.0 Via: SIP/2.0/UDP 54.203.245.50:5080;rport;branch=z9hG4bKUNeNtZcZp5ZmB Max-Forwards: 70 From: "" <sip:12026004299@54.203.245.50>;tag=9Z1HtD145Qv3K To: <sip:0011104555592211972@108.59.2.133> Call-ID: d7aeb7a1-6ac0-1232-718c-22000ad937f0 CSeq: 60838805 INVITE Contact: < sip:gw+voxbeam_outbound@54.203.245.50:5080;transport=udp;gw=voxbeam_outbound
User-Agent: FreeSWITCH-mod_sofia/1.2.24+git~20140603T002624Z~7b74ee3955~32bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Type: application/sdp Content-Disposition: session Content-Length: 207 X-FS-Support: update_display,send_info Remote-Party-ID: <sip:12026004299@54.203.245.50
;party=calling;screen=yes;privacy=off
v=0 o=FreeSWITCH 1402325141 1402325142 IN IP4 54.203.245.50 s=FreeSWITCH c=IN IP4 54.203.245.50 t=0 0 m=audio 24598 RTP/AVP 0 8 3 101 13 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ 2014-06-09 21:35:39.615207 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/0011104555592211972 [BREAK] 2014-06-09 21:35:39.615207 [DEBUG] switch_core_state_machine.c:418 (sofia/external/0011104555592211972) Running State Change CS_ROUTING 2014-06-09 21:35:39.615207 [DEBUG] sofia.c:5845 Channel sofia/external/0011104555592211972 entering state [calling][0] 2014-06-09 21:35:39.615207 [DEBUG] switch_core_state_machine.c:474 (sofia/external/0011104555592211972) State ROUTING 2014-06-09 21:35:39.615207 [DEBUG] mod_sofia.c:150 sofia/external/0011104555592211972 SOFIA ROUTING 2014-06-09 21:35:39.615207 [DEBUG] switch_ivr_originate.c:67 (sofia/external/0011104555592211972) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2014-06-09 21:35:39.615207 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/0011104555592211972 [BREAK] 2014-06-09 21:35:39.615207 [DEBUG] switch_core_state_machine.c:474 (sofia/external/0011104555592211972) State ROUTING going to sleep 2014-06-09 21:35:39.615207 [DEBUG] switch_core_state_machine.c:418 (sofia/external/0011104555592211972) Running State Change CS_CONSUME_MEDIA 2014-06-09 21:35:39.615207 [DEBUG] switch_core_state_machine.c:493 (sofia/external/0011104555592211972) State CONSUME_MEDIA 2014-06-09 21:35:39.615207 [DEBUG] switch_core_state_machine.c:493 (sofia/external/0011104555592211972) State CONSUME_MEDIA going to sleep recv 367 bytes from udp/[108.59.2.133]:5060 at 21:35:39.725204: ------------------------------------------------------------------------ SIP/2.0 100 Giving a try Via: SIP/2.0/UDP 54.203.245.50:5080 ;received=54.203.245.50;rport=5080;branch=z9hG4bKUNeNtZcZp5ZmB From: "" <sip:12026004299@54.203.245.50>;tag=9Z1HtD145Qv3K To: <sip:0011104555592211972@108.59.2.133> Call-ID: d7aeb7a1-6ac0-1232-718c-22000ad937f0 CSeq: 60838805 INVITE Server: OpenSIPS (1.8.2-notls (x86_64/linux)) Content-Length: 0
------------------------------------------------------------------------ recv 657 bytes from udp/[108.59.2.133]:5060 at 21:35:41.191275: ------------------------------------------------------------------------ SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 54.203.245.50:5080;rport;branch=z9hG4bKUNeNtZcZp5ZmB From: "" <sip:12026004299@54.203.245.50>;tag=9Z1HtD145Qv3K To: <sip:0011104555592211972@108.59.2.133>;tag=9312047651043624688 Call-ID: d7aeb7a1-6ac0-1232-718c-22000ad937f0 CSeq: 60838805 INVITE Content-Type: application/sdp Contact: <sip:callee@108.59.2.133;did=795.65454242> Supported: timer,100rel Content-Length: 226
v=0 o=RISNEXT02 869 1999 IN IP4 80.84.30.41 s=sip call c=IN IP4 80.84.30.41 t=0 0 m=audio 42108 RTP/AVP 0 13 101 a=rtpmap:0 PCMU/8000 a=rtpmap:13 CN/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ 2014-06-09 21:35:41.175213 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/0011104555592211972 [BREAK] 2014-06-09 21:35:41.175213 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/0011104555592211972 [BREAK] 2014-06-09 21:35:41.175213 [DEBUG] sofia.c:5845 Channel sofia/external/0011104555592211972 entering state [proceeding][183] 2014-06-09 21:35:41.175213 [DEBUG] sofia.c:5858 Remote SDP: v=0 o=RISNEXT02 869 1999 IN IP4 80.84.30.41 s=sip call c=IN IP4 80.84.30.41 t=0 0 m=audio 42108 RTP/AVP 0 13 101 a=rtpmap:0 PCMU/8000 a=rtpmap:13 CN/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20
2014-06-09 21:35:41.175213 [DEBUG] sofia_glue.c:5284 Audio Codec Compare [PCMU:0:8000:20:64000]/[PCMU:0:8000:20:64000] 2014-06-09 21:35:41.175213 [DEBUG] sofia_glue.c:3192 Set Codec sofia/external/0011104555592211972 PCMU/8000 20 ms 160 samples 64000 bits 2014-06-09 21:35:41.175213 [DEBUG] switch_core_codec.c:111 sofia/external/0011104555592211972 Original read codec set to PCMU:0 2014-06-09 21:35:41.175213 [DEBUG] sofia_glue.c:5444 Set 2833 dtmf send payload to 101 2014-06-09 21:35:41.175213 [DEBUG] sofia_glue.c:3451 AUDIO RTP [sofia/external/0011104555592211972] 10.217.55.240 port 24598 -> 80.84.30.41 port 42108 codec: 0 ms: 20 2014-06-09 21:35:41.175213 [DEBUG] switch_rtp.c:2040 Starting timer [soft] 160 bytes per 20ms 2014-06-09 21:35:41.175213 [DEBUG] sofia_glue.c:3718 Set 2833 dtmf send payload to 101 2014-06-09 21:35:41.175213 [DEBUG] sofia_glue.c:3724 Set 2833 dtmf receive payload to 101 2014-06-09 21:35:41.175213 [DEBUG] sofia_glue.c:3751 sofia/external/0011104555592211972 Set rtp dtmf delay to 40 2014-06-09 21:35:41.175213 [DEBUG] sofia_glue.c:3757 Set comfort noise payload to 13 2014-06-09 21:35:41.175213 [NOTICE] sofia_glue.c:4362 Pre-Answer sofia/external/0011104555592211972!
-- Sent from mobile device
Hmm, not sure thats true. You are not supposed to change codecs before the dialog is complete like this, its a violation of sdp o/a. On Jun 10, 2014, at 4:50 AM, Kristian Kielhofner <kris@kriskinc.com> wrote:
Hi Mark,
Thanks for providing the full log.
While goofy this is perfectly valid behavior. Because your instance of Freeswitch offers pcma and pcmu it's ok for the other side to switch between the two in 183.
A few things to try:
- Limit your outbound offers to pcma or pcmu only (one codec).
- The remote side appears to support 100rel (PRACK). Try enabling it in Freeswitch. While a long shot it's possible that PRACK'ing the initial received 183 might change the codec swap behavior of the remote end.
- Try Freeswitch 1.4 or master. There's been some significant changes in media/SDP behavior, particularly when the remote end does technically standards compliant but goofy things with multiple codec offers.
If none of these works you're only option may be to have the carrier take some action.
On Monday, June 9, 2014, Mark Boots <mark@votomobile.org> wrote: Hi Kristian,
I've narrowed this INCOMPATIBLE_DESTINATION error down to a specific case:
1 - Freeswitch sends the outgoing call, and offers PCMU/PCMA/GSM 2 - Other end accepts only PCMU 3 - At some point after Pre-answer, the other end issues a 183 Session Progress, changing to only accept PCMA. 4 - Freeswitch attempts to select new codecs but only looks at PCMU, and cancels the call with INCOMPATIBLE_DESTINATION.
Here is the console log and sip trace... Hope it helps!
+Mark
2014-06-09 21:35:39.615207 [DEBUG] switch_ivr_originate.c:2069 Parsing global variables 2014-06-09 21:35:39.615207 [DEBUG] switch_event.c:1661 Parsing variable [plivo_request_uuid]=[004fd8a2-f01e-11e3-844d-22000ad937f0] 2014-06-09 21:35:39.615207 [DEBUG] switch_event.c:1661 Parsing variable [plivo_answer_url]=[http://10.8.0.1/deliverylogs/answer/752471] 2014-06-09 21:35:39.615207 [DEBUG] switch_event.c:1661 Parsing variable [plivo_ring_url]=[http://127.0.0.1/callqueue/ring.php] 2014-06-09 21:35:39.615207 [DEBUG] switch_event.c:1661 Parsing variable [plivo_hangup_url]=[http://127.0.0.1/callqueue/hangup.php] 2014-06-09 21:35:39.615207 [DEBUG] switch_event.c:1661 Parsing variable [origination_caller_id_number]=[12026004299] 2014-06-09 21:35:39.615207 [DEBUG] switch_event.c:1661 Parsing variable [plivo_from]=[12026004299] 2014-06-09 21:35:39.615207 [DEBUG] switch_event.c:1661 Parsing variable [plivo_to]=[0011104555592211972] 2014-06-09 21:35:39.615207 [DEBUG] switch_event.c:1661 Parsing variable [plivo_app]=[true] 2014-06-09 21:35:39.615207 [DEBUG] switch_event.c:1661 Parsing variable [originate_timeout]=[60] 2014-06-09 21:35:39.615207 [DEBUG] switch_event.c:1661 Parsing variable [ignore_early_media]=[true] 2014-06-09 21:35:39.615207 [NOTICE] switch_channel.c:1049 New Channel sofia/external/0011104555592211972 [005052e6-f01e-11e3-bbae-cbf0f4eac998] 2014-06-09 21:35:39.615207 [DEBUG] mod_sofia.c:5237 (sofia/external/0011104555592211972) State Change CS_NEW -> CS_INIT 2014-06-09 21:35:39.615207 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/0011104555592211972 [BREAK] 2014-06-09 21:35:39.615207 [DEBUG] switch_core_state_machine.c:418 (sofia/external/0011104555592211972) Running State Change CS_INIT 2014-06-09 21:35:39.615207 [DEBUG] switch_core_state_machine.c:458 (sofia/external/0011104555592211972) State INIT 2014-06-09 21:35:39.615207 [DEBUG] mod_sofia.c:87 sofia/external/0011104555592211972 SOFIA INIT 2014-06-09 21:35:39.615207 [DEBUG] sofia_glue.c:2746 sofia/external/0011104555592211972 sending invite version: 1.2.24 git 7b74ee3 2014-06-03 00:26:24Z 32bit Local SDP: v=0 o=FreeSWITCH 1402325141 1402325142 IN IP4 54.203.245.50 s=FreeSWITCH c=IN IP4 54.203.245.50 t=0 0 m=audio 24598 RTP/AVP 0 8 3 101 13 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv
2014-06-09 21:35:39.615207 [DEBUG] mod_sofia.c:127 (sofia/external/0011104555592211972) State Change CS_INIT -> CS_ROUTING 2014-06-09 21:35:39.615207 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/0011104555592211972 [BREAK] 2014-06-09 21:35:39.615207 [DEBUG] switch_core_state_machine.c:458 (sofia/external/0011104555592211972) State INIT going to sleep send 1071 bytes to udp/[108.59.2.133]:5060 at 21:35:39.620673: ------------------------------------------------------------------------ INVITE sip:0011104555592211972@108.59.2.133 SIP/2.0 Via: SIP/2.0/UDP 54.203.245.50:5080;rport;branch=z9hG4bKUNeNtZcZp5ZmB Max-Forwards: 70 From: "" <sip:12026004299@54.203.245.50>;tag=9Z1HtD145Qv3K To: <sip:0011104555592211972@108.59.2.133> Call-ID: d7aeb7a1-6ac0-1232-718c-22000ad937f0 CSeq: 60838805 INVITE Contact: <sip:gw+voxbeam_outbound@54.203.245.50:5080;transport=udp;gw=voxbeam_outbound> User-Agent: FreeSWITCH-mod_sofia/1.2.24+git~20140603T002624Z~7b74ee3955~32bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Type: application/sdp Content-Disposition: session Content-Length: 207 X-FS-Support: update_display,send_info Remote-Party-ID: <sip:12026004299@54.203.245.50>;party=calling;screen=yes;privacy=off
v=0 o=FreeSWITCH 1402325141 1402325142 IN IP4 54.203.245.50 s=FreeSWITCH c=IN IP4 54.203.245.50 t=0 0 m=audio 24598 RTP/AVP 0 8 3 101 13 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ 2014-06-09 21:35:39.615207 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/0011104555592211972 [BREAK] 2014-06-09 21:35:39.615207 [DEBUG] switch_core_state_machine.c:418 (sofia/external/0011104555592211972) Running State Change CS_ROUTING 2014-06-09 21:35:39.615207 [DEBUG] sofia.c:5845 Channel sofia/external/0011104555592211972 entering state [calling][0] 2014-06-09 21:35:39.615207 [DEBUG] switch_core_state_machine.c:474 (sofia/external/0011104555592211972) State ROUTING 2014-06-09 21:35:39.615207 [DEBUG] mod_sofia.c:150 sofia/external/0011104555592211972 SOFIA ROUTING 2014-06-09 21:35:39.615207 [DEBUG] switch_ivr_originate.c:67 (sofia/external/0011104555592211972) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2014-06-09 21:35:39.615207 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/0011104555592211972 [BREAK] 2014-06-09 21:35:39.615207 [DEBUG] switch_core_state_machine.c:474 (sofia/external/0011104555592211972) State ROUTING going to sleep 2014-06-09 21:35:39.615207 [DEBUG] switch_core_state_machine.c:418 (sofia/external/0011104555592211972) Running State Change CS_CONSUME_MEDIA 2014-06-09 21:35:39.615207 [DEBUG] switch_core_state_machine.c:493 (sofia/external/0011104555592211972) State CONSUME_MEDIA 2014-06-09 21:35:39.615207 [DEBUG] switch_core_state_machine.c:493 (sofia/external/0011104555592211972) State CONSUME_MEDIA going to sleep recv 367 bytes from udp/[108.59.2.133]:5060 at 21:35:39.725204: ------------------------------------------------------------------------ SIP/2.0 100 Giving a try Via: SIP/2.0/UDP 54.203.245.50:5080;received=54.203.245.50;rport=5080;branch=z9hG4bKUNeNtZcZp5ZmB From: "" <sip:12026004299@54.203.245.50>;tag=9Z1HtD145Qv3K To: <sip:0011104555592211972@108.59.2.133> Call-ID: d7aeb7a1-6ac0-1232-718c-22000ad937f0 CSeq: 60838805 INVITE Server: OpenSIPS (1.8.2-notls (x86_64/linux)) Content-Length: 0
------------------------------------------------------------------------ recv 657 bytes from udp/[108.59.2.133]:5060 at 21:35:41.191275: ------------------------------------------------------------------------ SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 54.203.245.50:5080;rport;branch=z9hG4bKUNeNtZcZp5ZmB From: "" <sip:12026004299@54.203.245.50>;tag=9Z1HtD145Qv3K To: <sip:0011104555592211972@108.59.2.133>;tag=9312047651043624688 Call-ID: d7aeb7a1-6ac0-1232-718c-22000ad937f0 CSeq: 60838805 INVITE Content-Type: application/sdp Contact: <sip:callee@108.59.2.133;did=795.65454242> Supported: timer,100rel Content-Length: 226
v=0 o=RISNEXT02 869 1999 IN IP4 80.84.30.41 s=sip call c=IN IP4 80.84.30.41 t=0 0 m=audio 42108 RTP/AVP 0 13 101 a=rtpmap:0 PCMU/8000 a=rtpmap:13 CN/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 ------------------------------------------------------------------------ 2014-06-09 21:35:41.175213 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/0011104555592211972 [BREAK] 2014-06-09 21:35:41.175213 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/0011104555592211972 [BREAK] 2014-06-09 21:35:41.175213 [DEBUG] sofia.c:5845 Channel sofia/external/0011104555592211972 entering state [proceeding][183] 2014-06-09 21:35:41.175213 [DEBUG] sofia.c:5858 Remote SDP: v=0 o=RISNEXT02 869 1999 IN IP4 80.84.30.41 s=sip call c=IN IP4 80.84.30.41 t=0 0 m=audio 42108 RTP/AVP 0 13 101 a=rtpmap:0 PCMU/8000 a=rtpmap:13 CN/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20
2014-06-09 21:35:41.175213 [DEBUG] sofia_glue.c:5284 Audio Codec Compare [PCMU:0:8000:20:64000]/[PCMU:0:8000:20:64000] 2014-06-09 21:35:41.175213 [DEBUG] sofia_glue.c:3192 Set Codec sofia/external/0011104555592211972 PCMU/8000 20 ms 160 samples 64000 bits 2014-06-09 21:35:41.175213 [DEBUG] switch_core_codec.c:111 sofia/external/0011104555592211972 Original read codec set to PCMU:0 2014-06-09 21:35:41.175213 [DEBUG] sofia_glue.c:5444 Set 2833 dtmf send payload to 101 2014-06-09 21:35:41.175213 [DEBUG] sofia_glue.c:3451 AUDIO RTP [sofia/external/0011104555592211972] 10.217.55.240 port 24598 -> 80.84.30.41 port 42108 codec: 0 ms: 20 2014-06-09 21:35:41.175213 [DEBUG] switch_rtp.c:2040 Starting timer [soft] 160 bytes per 20ms 2014-06-09 21:35:41.175213 [DEBUG] sofia_glue.c:3718 Set 2833 dtmf send payload to 101 2014-06-09 21:35:41.175213 [DEBUG] sofia_glue.c:3724 Set 2833 dtmf receive payload to 101 2014-06-09 21:35:41.175213 [DEBUG] sofia_glue.c:3751 sofia/external/0011104555592211972 Set rtp dtmf delay to 40 2014-06-09 21:35:41.175213 [DEBUG] sofia_glue.c:3757 Set comfort noise payload to 13 2014-06-09 21:35:41.175213 [NOTICE] sofia_glue.c:4362 Pre-Answer sofia/external/0011104555592211972!
Hi Mike, It's fairly typical in proxy forking scenarios. In this case the received 183s have different To tags, which indicates forking on the proxy and two distinct dialogs. As I said in my original message I'd be very interested to see what happens when PRACK/100rel is enabled in this scenario. Personally speaking I don't like when providers use wildly different upstream carriers in conjunction with a proxy because you end up with situations like this and the inevitable variances in end-user experience. On Tue, Jun 10, 2014 at 8:42 AM, Michael Jerris <mike@jerris.com> wrote:
Hmm, not sure thats true. You are not supposed to change codecs before the dialog is complete like this, its a violation of sdp o/a.
On Jun 10, 2014, at 4:50 AM, Kristian Kielhofner <kris@kriskinc.com> wrote:
Hi Mark,
Thanks for providing the full log.
While goofy this is perfectly valid behavior. Because your instance of Freeswitch offers pcma and pcmu it's ok for the other side to switch between the two in 183.
A few things to try:
- Limit your outbound offers to pcma or pcmu only (one codec).
- The remote side appears to support 100rel (PRACK). Try enabling it in Freeswitch. While a long shot it's possible that PRACK'ing the initial received 183 might change the codec swap behavior of the remote end.
- Try Freeswitch 1.4 or master. There's been some significant changes in media/SDP behavior, particularly when the remote end does technically standards compliant but goofy things with multiple codec offers.
If none of these works you're only option may be to have the carrier take some action.
On Monday, June 9, 2014, Mark Boots <mark@votomobile.org> wrote:
Hi Kristian,
I've narrowed this INCOMPATIBLE_DESTINATION error down to a specific case:
1 - Freeswitch sends the outgoing call, and offers PCMU/PCMA/GSM 2 - Other end accepts only PCMU 3 - At some point after Pre-answer, the other end issues a 183 Session Progress, changing to only accept PCMA. 4 - Freeswitch attempts to select new codecs but only looks at PCMU, and cancels the call with INCOMPATIBLE_DESTINATION.
Here is the console log and sip trace... Hope it helps!
+Mark
2014-06-09 21:35:39.615207 [DEBUG] switch_ivr_originate.c:2069 Parsing global variables 2014-06-09 21:35:39.615207 [DEBUG] switch_event.c:1661 Parsing variable [plivo_request_uuid]=[004fd8a2-f01e-11e3-844d-22000ad937f0] 2014-06-09 21:35:39.615207 [DEBUG] switch_event.c:1661 Parsing variable [plivo_answer_url]=[http://10.8.0.1/deliverylogs/answer/752471] 2014-06-09 21:35:39.615207 [DEBUG] switch_event.c:1661 Parsing variable [plivo_ring_url]=[http://127.0.0.1/callqueue/ring.php] 2014-06-09 21:35:39.615207 [DEBUG] switch_event.c:1661 Parsing variable [plivo_hangup_url]=[http://127.0.0.1/callqueue/hangup.php] 2014-06-09 21:35:39.615207 [DEBUG] switch_event.c:1661 Parsing variable [origination_caller_id_number]=[12026004299] 2014-06-09 21:35:39.615207 [DEBUG] switch_event.c:1661 Parsing variable [plivo_from]=[12026004299] 2014-06-09 21:35:39.615207 [DEBUG] switch_event.c:1661 Parsing variable [plivo_to]=[0011104555592211972] 2014-06-09 21:35:39.615207 [DEBUG] switch_event.c:1661 Parsing variable [plivo_app]=[true] 2014-06-09 21:35:39.615207 [DEBUG] switch_event.c:1661 Parsing variable [originate_timeout]=[60] 2014-06-09 21:35:39.615207 [DEBUG] switch_event.c:1661 Parsing variable [ignore_early_media]=[true] 2014-06-09 21:35:39.615207 [NOTICE] switch_channel.c:1049 New Channel sofia/external/0011104555592211972 [005052e6-f01e-11e3-bbae-cbf0f4eac998] 2014-06-09 21:35:39.615207 [DEBUG] mod_sofia.c:5237 (sofia/external/0011104555592211972) State Change CS_NEW -> CS_INIT 2014-06-09 21:35:39.615207 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/0011104555592211972 [BREAK] 2014-06-09 21:35:39.615207 [DEBUG] switch_core_state_machine.c:418 (sofia/external/0011104555592211972) Running State Change CS_INIT 2014-06-09 21:35:39.615207 [DEBUG] switch_core_state_machine.c:458 (sofia/external/0011104555592211972) State INIT 2014-06-09 21:35:39.615207 [DEBUG] mod_sofia.c:87 sofia/external/0011104555592211972 SOFIA INIT 2014-06-09 21:35:39.615207 [DEBUG] sofia_glue.c:2746 sofia/external/0011104555592211972 sending invite version: 1.2.24 git 7b74ee3 2014-06-03 00:26:24Z 32bit Local SDP: v=0 o=FreeSWITCH 1402325141 1402325142 IN IP4 54.203.245.50 s=FreeSWITCH c=IN IP4 54.203.245.50 t=0 0 m=audio 24598 RTP/AVP 0 8 3 101 13 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv
2014-06-09 21:35:39.615207 [DEBUG] mod_sofia.c:127 (sofia/external/0011104555592211972) State Change CS_INIT -> CS_ROUTING 2014-06-09 21:35:39.615207 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/0011104555592211972 [BREAK] 2014-06-09 21:35:39.615207 [DEBUG] switch_core_state_machine.c:458 (sofia/external/0011104555592211972) State INIT going to sleep send 1071 bytes to udp/[108.59.2.133]:5060 at 21:35:39.620673:
------------------------------------------------------------------------ INVITE sip:0011104555592211972@108.59.2.133 SIP/2.0 Via: SIP/2.0/UDP 54.203.245.50:5080;rport;branch=z9hG4bKUNeNtZcZp5ZmB Max-Forwards: 70 From: "" <sip:12026004299@54.203.245.50>;tag=9Z1HtD145Qv3K To: <sip:0011104555592211972@108.59.2.133> Call-ID: d7aeb7a1-6ac0-1232-718c-22000ad937f0 CSeq: 60838805 INVITE Contact: <sip:gw+voxbeam_outbound@54.203.245.50:5080;transport=udp;gw=voxbeam_outbound> User-Agent: FreeSWITCH-mod_sofia/1.2.24+git~20140603T002624Z~7b74ee3955~32bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Content-Type: application/sdp Content-Disposition: session Content-Length: 207 X-FS-Support: update_display,send_info Remote-Party-ID: <sip:12026004299@54.203.245.50>;party=calling;screen=yes;privacy=off
v=0 o=FreeSWITCH 1402325141 1402325142 IN IP4 54.203.245.50 s=FreeSWITCH c=IN IP4 54.203.245.50 t=0 0 m=audio 24598 RTP/AVP 0 8 3 101 13 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20
------------------------------------------------------------------------ 2014-06-09 21:35:39.615207 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/0011104555592211972 [BREAK] 2014-06-09 21:35:39.615207 [DEBUG] switch_core_state_machine.c:418 (sofia/external/0011104555592211972) Running State Change CS_ROUTING 2014-06-09 21:35:39.615207 [DEBUG] sofia.c:5845 Channel sofia/external/0011104555592211972 entering state [calling][0] 2014-06-09 21:35:39.615207 [DEBUG] switch_core_state_machine.c:474 (sofia/external/0011104555592211972) State ROUTING 2014-06-09 21:35:39.615207 [DEBUG] mod_sofia.c:150 sofia/external/0011104555592211972 SOFIA ROUTING 2014-06-09 21:35:39.615207 [DEBUG] switch_ivr_originate.c:67 (sofia/external/0011104555592211972) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2014-06-09 21:35:39.615207 [DEBUG] switch_core_session.c:1351 Send signal sofia/external/0011104555592211972 [BREAK] 2014-06-09 21:35:39.615207 [DEBUG] switch_core_state_machine.c:474 (sofia/external/0011104555592211972) State ROUTING going to sleep 2014-06-09 21:35:39.615207 [DEBUG] switch_core_state_machine.c:418 (sofia/external/0011104555592211972) Running State Change CS_CONSUME_MEDIA 2014-06-09 21:35:39.615207 [DEBUG] switch_core_state_machine.c:493 (sofia/external/0011104555592211972) State CONSUME_MEDIA 2014-06-09 21:35:39.615207 [DEBUG] switch_core_state_machine.c:493 (sofia/external/0011104555592211972) State CONSUME_MEDIA going to sleep recv 367 bytes from udp/[108.59.2.133]:5060 at 21:35:39.725204:
------------------------------------------------------------------------ SIP/2.0 100 Giving a try Via: SIP/2.0/UDP 54.203.245.50:5080;received=54.203.245.50;rport=5080;branch=z9hG4bKUNeNtZcZp5ZmB From: "" <sip:12026004299@54.203.245.50>;tag=9Z1HtD145Qv3K To: <sip:0011104555592211972@108.59.2.133> Call-ID: d7aeb7a1-6ac0-1232-718c-22000ad937f0 CSeq: 60838805 INVITE Server: OpenSIPS (1.8.2-notls (x86_64/linux)) Content-Length: 0
------------------------------------------------------------------------ recv 657 bytes from udp/[108.59.2.133]:5060 at 21:35:41.191275:
------------------------------------------------------------------------ SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 54.203.245.50:5080;rport;branch=z9hG4bKUNeNtZcZp5ZmB From: "" <sip:12026004299@54.203.245.50>;tag=9Z1HtD145Qv3K To: <sip:0011104555592211972@108.59.2.133>;tag=9312047651043624688 Call-ID: d7aeb7a1-6ac0-1232-718c-22000ad937f0 CSeq: 60838805 INVITE Content-Type: application/sdp Contact: <sip:callee@108.59.2.133;did=795.65454242> Supported: timer,100rel Content-Length: 226
v=0 o=RISNEXT02 869 1999 IN IP4 80.84.30.41 s=sip call c=IN IP4 80.84.30.41 t=0 0 m=audio 42108 RTP/AVP 0 13 101 a=rtpmap:0 PCMU/8000 a=rtpmap:13 CN/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20
------------------------------------------------------------------------ 2014-06-09 21:35:41.175213 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/0011104555592211972 [BREAK] 2014-06-09 21:35:41.175213 [DEBUG] switch_core_session.c:1016 Send signal sofia/external/0011104555592211972 [BREAK] 2014-06-09 21:35:41.175213 [DEBUG] sofia.c:5845 Channel sofia/external/0011104555592211972 entering state [proceeding][183] 2014-06-09 21:35:41.175213 [DEBUG] sofia.c:5858 Remote SDP: v=0 o=RISNEXT02 869 1999 IN IP4 80.84.30.41 s=sip call c=IN IP4 80.84.30.41 t=0 0 m=audio 42108 RTP/AVP 0 13 101 a=rtpmap:0 PCMU/8000 a=rtpmap:13 CN/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20
2014-06-09 21:35:41.175213 [DEBUG] sofia_glue.c:5284 Audio Codec Compare [PCMU:0:8000:20:64000]/[PCMU:0:8000:20:64000] 2014-06-09 21:35:41.175213 [DEBUG] sofia_glue.c:3192 Set Codec sofia/external/0011104555592211972 PCMU/8000 20 ms 160 samples 64000 bits 2014-06-09 21:35:41.175213 [DEBUG] switch_core_codec.c:111 sofia/external/0011104555592211972 Original read codec set to PCMU:0 2014-06-09 21:35:41.175213 [DEBUG] sofia_glue.c:5444 Set 2833 dtmf send payload to 101 2014-06-09 21:35:41.175213 [DEBUG] sofia_glue.c:3451 AUDIO RTP [sofia/external/0011104555592211972] 10.217.55.240 port 24598 -> 80.84.30.41 port 42108 codec: 0 ms: 20 2014-06-09 21:35:41.175213 [DEBUG] switch_rtp.c:2040 Starting timer [soft] 160 bytes per 20ms 2014-06-09 21:35:41.175213 [DEBUG] sofia_glue.c:3718 Set 2833 dtmf send payload to 101 2014-06-09 21:35:41.175213 [DEBUG] sofia_glue.c:3724 Set 2833 dtmf receive payload to 101 2014-06-09 21:35:41.175213 [DEBUG] sofia_glue.c:3751 sofia/external/0011104555592211972 Set rtp dtmf delay to 40 2014-06-09 21:35:41.175213 [DEBUG] sofia_glue.c:3757 Set comfort noise payload to 13 2014-06-09 21:35:41.175213 [NOTICE] sofia_glue.c:4362 Pre-Answer sofia/external/0011104555592211972!
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
-- Kristian Kielhofner
participants (3)
-
Kristian Kielhofner
-
Mark Boots
-
Michael Jerris