Uploaded image for project: 'FreeSWITCH'
  1. FreeSWITCH
  2. FS-10089

Combining inherit_codec and ICE can lead to dropped calls

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Minor
    • Resolution: No Reporter Response
    • Affects Version/s: None
    • Fix Version/s: None
    • Component/s: core, mod_sofia
    • Labels:
      None
    • Environment:
      Debian 8 container running on Amazon Linux
    • CPU Architecture:
      x86-64
    • Kernel:
      Linux
    • Userland:
      GNU/Linux
    • Distribution:
      Debian
    • Distribution Version:
      Debian 8 jessie
    • Compiler:
      gcc
    • FreeSWITCH GIT Revision:
      e8bd2d6
    • GIT Master Revision hash::
      7b8465915b08b631f1fdfae15847b06407386a44

      Description

      It looks like the combination of inherit_codec and ICE can result in inconsistent state in Freeswitch.

      Specifically, this is the scenario that is happening:

      1. Caller sends INVITE with three media options:

      a=rtpmap:120 opus/48000/2
      a=fmtp:120 useinbandfec=1
      a=rtpmap:0 PCMU/8000
      a=rtpmap:96 telephone-event/8000

      2. Freeswitch bridges call to remote, gets PCMU in the response, sends 200 OK to caller with:

      a=rtpmap:0 PCMU/8000
      a=rtpmap:96 telephone-event/8000

      3. Caller sends ICE update request with the same three codecs from the original INVITE (I don't know the spec well enough to know if this is right, but it seems fine)

      a=rtpmap:120 opus/48000/2
      a=fmtp:120 useinbandfec=1
      a=rtpmap:0 PCMU/8000
      a=rtpmap:96 telephone-event/80

      4. Freeswitch, again, correctly responds with PCMU

      a=rtpmap:0 PCMU/8000
      a=rtpmap:96 telephone-event/8000

      However, this is where things start to go go wrong. FS then continues on to look at the SDP for codec comparison:

      2017-03-03 19:54:57.826432 [DEBUG] switch_core_media.c:1460 looking for crypto suite [AEAD_AES_256_GCM_8] in [3 AES_CM_128_HMAC_SHA1_80 inline:lm5GFVTjapvfDLzF58F4cETaVmXDsLBSilWIFIAY]
      2017-03-03 19:54:57.826432 [DEBUG] switch_core_media.c:1460 looking for crypto suite [AEAD_AES_128_GCM_8] in [3 AES_CM_128_HMAC_SHA1_80 inline:lm5GFVTjapvfDLzF58F4cETaVmXDsLBSilWIFIAY]
      2017-03-03 19:54:57.826432 [DEBUG] switch_core_media.c:1460 looking for crypto suite [AES_CM_256_HMAC_SHA1_80] in [3 AES_CM_128_HMAC_SHA1_80 inline:lm5GFVTjapvfDLzF58F4cETaVmXDsLBSilWIFIAY]
      2017-03-03 19:54:57.826432 [DEBUG] switch_core_media.c:1460 looking for crypto suite [AES_CM_192_HMAC_SHA1_80] in [3 AES_CM_128_HMAC_SHA1_80 inline:lm5GFVTjapvfDLzF58F4cETaVmXDsLBSilWIFIAY]
      2017-03-03 19:54:57.826432 [DEBUG] switch_core_media.c:1460 looking for crypto suite [AES_CM_128_HMAC_SHA1_80] in [3 AES_CM_128_HMAC_SHA1_80 inline:lm5GFVTjapvfDLzF58F4cETaVmXDsLBSilWIFIAY]
      2017-03-03 19:54:57.826432 [DEBUG] switch_core_media.c:1465 Found suite AES_CM_128_HMAC_SHA1_80
      2017-03-03 19:54:57.826432 [DEBUG] switch_core_media.c:1474 Existing key is still valid.
      2017-03-03 19:54:57.826432 [DEBUG] switch_core_media.c:4858 Audio Codec Compare [opus:120:48000:20:0:1]/[opus:116:48000:20:0:1]
      2017-03-03 19:54:57.826432 [DEBUG] switch_core_media.c:4913 Audio Codec Compare [opus:116:48000:20:0:1] ++++ is saved as a match
      2017-03-03 19:54:57.826432 [DEBUG] switch_core_media.c:4858 Audio Codec Compare [opus:120:48000:20:0:1]/[PCMU:0:8000:20:64000:1]
      2017-03-03 19:54:57.826432 [DEBUG] switch_core_media.c:4858 Audio Codec Compare [opus:120:48000:20:0:1]/[PCMA:8:8000:20:64000:1]
      2017-03-03 19:54:57.826432 [DEBUG] switch_core_media.c:4858 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]
      2017-03-03 19:54:57.826432 [DEBUG] switch_core_media.c:4858 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
      2017-03-03 19:54:57.826432 [DEBUG] switch_core_media.c:4913 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
      2017-03-03 19:54:57.826432 [DEBUG] switch_core_media.c:4858 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
      2017-03-03 19:54:57.826432 [DEBUG] switch_core_media.c:4774 Set telephone-event payload to 96@8000
      2017-03-03 19:54:57.826432 [DEBUG] switch_core_media.c:3807 Save audio Candidate cid: 1 proto: UDP type: prflx addr: 68.132.236.170:54782
      2017-03-03 19:54:57.826432 [DEBUG] switch_core_media.c:3807 Save audio Candidate cid: 1 proto: UDP type: prflx addr: 169.254.169.254:54782
      2017-03-03 19:54:57.826432 [DEBUG] switch_core_media.c:3849 Searching for rtp candidate.
      2017-03-03 19:54:57.826432 [DEBUG] switch_core_media.c:3854 Choose rtp candidate, index 0, 68.132.236.170:54782
      2017-03-03 19:54:57.826432 [DEBUG] switch_core_media.c:3628 sofia/internal/channel choosing family v4
      2017-03-03 19:54:57.826432 [DEBUG] switch_core_media.c:3849 Searching for rtcp candidate.
      2017-03-03 19:54:57.826432 [DEBUG] switch_core_media.c:3910 setting remote audio ice addr to index 0 68.132.236.170:54782 based on candidate
      2017-03-03 19:54:57.826432 [DEBUG] switch_core_media.c:5176 sofia/internal/channel Set 2833 dtmf send payload to 96 recv payload to 96
      2017-03-03 19:54:57.826432 [DEBUG] sofia.c:8205 Processing updated SDP
      2017-03-03 19:54:57.826432 [DEBUG] switch_core_media.c:7757 Audio params changed for sofia/internal/channel from 169.254.169.254:54782 to 68.132.236.170:54782
      2017-03-03 19:54:57.826432 [DEBUG] switch_core_media.c:7768 AUDIO RTP [sofia/internal/channel] 172.16.1.219 port 22568 -> 68.132.236.170 port 54782 codec: 120 ms: 20
      2017-03-03 19:54:57.826432 [DEBUG] switch_core_media.c:7797 AUDIO RTP CHANGING DEST TO: [68.132.236.170:54782]
      2017-03-03 19:54:57.846375 [DEBUG] switch_core_media.c:3287 Changing Codec from PCMU@20ms@8000hz to opus@20ms@48000hz

      Presumably, because opus appears first - and FS supports it - it selects that codec. However, it responded in the SDP that it was accepting PCMU. The client correctly sends PCMU, which causes:

      2017-03-03 19:54:57.946410 [DEBUG] switch_rtp.c:7019 Correct audio ip/port confirmed.
      2017-03-03 19:54:57.946410 [DEBUG] switch_core_media.c:2849 alternate payload received (received 0, expecting 120)
      2017-03-03 19:54:57.946410 [WARNING] switch_core_media.c:2860 Changing current codec to PCMU (payload type 0).
      2017-03-03 19:54:57.946410 [ERR] mod_opus.c:884 Decoder Error: corrupted stream fs:4080 plc:false!
      2017-03-03 19:54:57.946410 [ERR] switch_core_media.c:14775 Codec OPUS (STANDARD) decoder error!
      2017-03-03 19:54:57.946410 [DEBUG] switch_ivr_bridge.c:792 sofia/internal/otherleg ending bridge by request from write function

      Whether or not the last line appears and the bridge ends seems to be a race condition of some sorts. Sometimes the call continues on fine, other times it seems to abruptly end.

      My knowledge of the spec is fairly minimal here, so it's possible the client shouldn't be sending the opus codec in the followup UPDATE request. However, even if that were the case, FS still seems to have a disagreement between what it sends back to the caller and what it actually does.

      Will upload raw logs shortly

        Attachments

          Issue Links

            Activity

              People

              • Assignee:
                mikej Mike Jerris
                Reporter:
                colin.morelli@gmail.com Colin Morelli
              • Votes:
                0 Vote for this issue
                Watchers:
                3 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: