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

switch_rtp mistakes "ffffffff" for a new DTMF and Queue's a NULL digit

    Details

    • Type: Bug
    • Status: Resolved
    • Priority: Minor
    • Resolution: Fixed
    • Affects Version/s: 1.6.12
    • Fix Version/s: None
    • Component/s: core
    • Security Level: public
    • Labels:
      None
    • Environment:
      Linux qa-fsw-nvaaws-a02 3.10.0-327.18.2.el7.x86_64 #1 SMP Thu May 12 11:03:55 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux

      FreeSWITCH Version 1.6.12+git~20161114T235829Z~2f7fd1e60c~64bit (git 2f7fd1e 2016-11-14 23:58:29Z 64bit)
    • CPU Architecture:
      x86-64
    • Kernel:
      Linux
    • uname:
      Linux qa-fsw-nvaaws-a02 3.10.0-327.18.2.el7.x86_64 #1 SMP Thu May 12 11:03:55 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux
    • Userland:
      GNU/Linux
    • Distribution:
      CentOS
    • Distribution Version:
      CentOS 7
    • lsb_release:
      Hide
      -bash: lsb_release: command not found
      Show
      -bash: lsb_release: command not found
    • Compiler:
      gcc
    • Compiler Version:
      gcc (GCC) 4.8.5 20150623 (Red Hat 4.8.5-4)
    • FreeSWITCH GIT Revision:
      FreeSWITCH Version 1.6.12+git~20161114T235829Z~2f7fd1e60c~64bit (git 2f7fd1e 2016-11-14 23:58:29Z 64bit)
    • GIT Master Revision hash::
      n/a

      Description

      Trying to debug why incoming DTMFs are sometimes dropped.
      Have upgraded to latest v1.6 and tested with DEBUG_2833 on.

      The main symptom we sometimes see in the log is:
      switch_rtp.c:7187 RTP RECV DTMF
      with NO identified digit. (eg line 2343 in attached log)

      This was preceded by an all F's packet:
      packet[160]: ff ff ff ff
      (line 2326 in log)

      As far as I can tell looking at the code, this causes the "key" variable to be set to '\0' at switch_rtp.c:617.
      "duration" is presumably set to 0xffff, and "end" is set to 1 since 0xff & 0x80 is going to be true (line 615).

      The "key" variable then is used to populate dtmf.digit (and maybe other fields...)

      This leads to many "truncated" log statements including:
      line 646 "read: "
      line 711: "done: "
      line 717 "Queuing digit "
      (example lines: 2327 and 2328)

      It seems that this "NULL" dtmf has been mis-identified somehow and should not be "Queued" as a digit.

      I noticed that this was logged:
      switch_rtp.c:690 start with end packet 163360
      Seems to indicate that FS thinks a new DTMF is starting, but is also immediately "done" due to the "end" var being set.


      I see in the log (line 2329) that FS then "drops" the next several packets which are the start of a new "#" dtmf, until line 2346 when a "start" is shown (though we are 50ms into the new dtmf).

      At line 2375 another "ffffffff" is received but this time it is dropped (although the log statement is truncated due to the NULL). Then a couple of "#" packets are also dropped for some reason (2378 and 2382).

      The "#" dtmf then continues until 2413 when the "end" is reached for a duration of 270ms.

      So in this case I don't think anything was "dropped" - but I wanted to submit the issue b/c it seems the falsely identified "NULL" digit does cause some packets to be ignored, and I wonder if this could explain other calls I've had, where the "RECV DTMF$" is NOT followed by a true dtmf detection. Unfortunately I haven't had a call like that with the DEBUG_2833 engaged yet.

      Thanks for your help.



      1. freeswitch.kp.log
        355 kB
        Mitch Chapman
      2. fs.pcap.log
        154 kB
        Mitch Chapman
      3. pcap.out
        515 kB
        Mitch Chapman

        Activity

        Hide
        brian Brian West added a comment -
        What IP is what?
        Show
        brian Brian West added a comment - What IP is what?
        Hide
        brian Brian West added a comment -
        FreeSWITCH 172.31.30.16
        Sonus 67.231.9.83

        So all these packets that are being interpreted wrong are coming from a Sonus, You may have to activate various RTP BUGS to overcome this issue,

        https://freeswitch.org/confluence/display/FREESWITCH/RTP+Issues

        Also you're playing raw .alaw files, Those will still get transcode via sndfile, You need to call them .PCMU if you wish to use native files. But you're attaching a bug to the session so native files is a moot point, you gain nothing by doing this.

        https://freeswitch.org/confluence/display/FREESWITCH/mod_native_file
        Show
        brian Brian West added a comment - FreeSWITCH 172.31.30.16 Sonus 67.231.9.83 So all these packets that are being interpreted wrong are coming from a Sonus, You may have to activate various RTP BUGS to overcome this issue, https://freeswitch.org/confluence/display/FREESWITCH/RTP+Issues Also you're playing raw .alaw files, Those will still get transcode via sndfile, You need to call them .PCMU if you wish to use native files. But you're attaching a bug to the session so native files is a moot point, you gain nothing by doing this. https://freeswitch.org/confluence/display/FREESWITCH/mod_native_file
        Hide
        kidplug Mitch Chapman added a comment -
        Our audio files are raw ulaw actually. I presume your same comments still hold.
        Show
        kidplug Mitch Chapman added a comment - Our audio files are raw ulaw actually. I presume your same comments still hold.
        Hide
        brian Brian West added a comment -
        Yes, .ulaw is processed by libsndfile, while .PCMU is processed by native sounds module.

        As for your DTMF issue:

        RTP_BUG_IGNORE_DTMF_DURATION = (1 << 6),
        Guess Who? ... Yep, Sonus (and who know's who else) likes to interweave DTMF with the audio stream making it take
        2X as long as it should and sending an incorrect duration making the DTMF very delayed.
        This flag will treat every dtmf as if it were 50ms and queue it on recipt of the leading packet rather than at the end.
        Show
        brian Brian West added a comment - Yes, .ulaw is processed by libsndfile, while .PCMU is processed by native sounds module. As for your DTMF issue: RTP_BUG_IGNORE_DTMF_DURATION = (1 << 6), Guess Who? ... Yep, Sonus (and who know's who else) likes to interweave DTMF with the audio stream making it take 2X as long as it should and sending an incorrect duration making the DTMF very delayed. This flag will treat every dtmf as if it were 50ms and queue it on recipt of the leading packet rather than at the end.
        Hide
        kidplug Mitch Chapman added a comment -
        Brian - I already tried that "BUG" setting - and it does what it claims to do - it does detect and Q the DTMF on the very first packet received.
        However, [sometimes] audio packets STILL get picked up during do_flush() and passed to handle_rfc2833() - which appear to be an "end" to the DTMF, and that causes the next real DTMF packet to trigger a NEW digit (which is immediately Queued).
        This results in a double detect of a single DTMF event.
        So I don't think this is a suitable fix - it does nothing to deal with the simple fact that audio packets are mistakenly "handled" as rfc2833 packets and cause all sorts of logic and logging errors.
        Show
        kidplug Mitch Chapman added a comment - Brian - I already tried that "BUG" setting - and it does what it claims to do - it does detect and Q the DTMF on the very first packet received. However, [sometimes] audio packets STILL get picked up during do_flush() and passed to handle_rfc2833() - which appear to be an "end" to the DTMF, and that causes the next real DTMF packet to trigger a NEW digit (which is immediately Queued). This results in a double detect of a single DTMF event. So I don't think this is a suitable fix - it does nothing to deal with the simple fact that audio packets are mistakenly "handled" as rfc2833 packets and cause all sorts of logic and logging errors.

          People

          • Assignee:
            mikej Mike Jerris
            Reporter:
            kidplug Mitch Chapman
          • Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development