I'm coming across a strange, intermittent behavior with RFC2833 DTMF packets. This is occurring in a production environment, and I've been able to duplicate this with a very minimal FreeSWITCH installation in a virtual machine. Details of the problem: A customer occasionally has a problem report where their callers are unable to use the IVR menu. From the user's standpoint, the digits are not detected. Upon further review, we do receive DTMF event packets from the carrier, however, they do not traverse the bridge from the A leg to the B leg.
From the console logs, I see the following with the first digit. -- 2021-02-20 11:28:30.842108 [DEBUG] mod_sofia.c:645 SOFIA EXCHANGE_MEDIA 2021-02-20 11:28:30.881612 [DEBUG] switch_rtp.c:1890 rtcp_stats_init: audio ssrc[1488669269] base_seq[26830] 2021-02-20 11:28:30.933002 [DEBUG] switch_rtp.c:7550 Correct audio ip/port confirmed. 2021-02-20 11:28:34.881612 [DEBUG] switch_rtp.c:7550 Correct audio ip/port confirmed. 2021-02-20 11:28:34.923555 [DEBUG] switch_rtp.c:7789 RTP RECV DTMF 1:400 2021-02-20 11:28:34.923555 [INFO] switch_channel.c:515 RECV DTMF 1:400 2021-02-20 11:28:34.923555 [DEBUG] switch_rtp.c:5424 Send start packet for [1] ts=160 dur=160/160/400 seq=51938 lw=160 2021-02-20 11:28:34.942196 [DEBUG] switch_rtp.c:5323 Send middle packet for [1] ts=160 dur=320/320/400 seq=51939 lw=320 2021-02-20 11:28:34.942196 [DEBUG] switch_rtp.c:5323 Send end packet for [1] ts=160 dur=480/480/400 seq=51940 lw=320 2021-02-20 11:28:34.942196 [DEBUG] switch_rtp.c:5323 Send end packet for [1] ts=160 dur=480/480/400 seq=51941 lw=320 2021-02-20 11:28:34.942196 [DEBUG] switch_rtp.c:5323 Send end packet for [1] ts=160 dur=480/480/400 seq=51942 lw=320 2021-02-20 11:28:34.942196 [DEBUG] switch_rtp.c:5271 Queue digit delay of 40ms 2021-02-20 11:28:35.421487 [DEBUG] switch_rtp.c:6985 Correct audio RTCP ip/port confirmed. --
However, on the following series of digits, they are detected as seen in the logs from switch_rtp.c and switch_channel.c. However, they do not proceed to the "Send start packet" step as seen with the previous digit. This mirrors what I see on the B leg client, as it only detects the first digit. -- 2021-02-20 11:28:37.521489 [DEBUG] switch_rtp.c:7789 RTP RECV DTMF 1:400 2021-02-20 11:28:37.521489 [INFO] switch_channel.c:515 RECV DTMF 1:400 2021-02-20 11:28:46.082031 [DEBUG] switch_rtp.c:7789 RTP RECV DTMF 3:400 2021-02-20 11:28:46.082031 [INFO] switch_channel.c:515 RECV DTMF 3:400 2021-02-20 11:28:46.481377 [DEBUG] switch_rtp.c:7789 RTP RECV DTMF 6:400 2021-02-20 11:28:46.481377 [INFO] switch_channel.c:515 RECV DTMF 6:400 2021-02-20 11:28:47.061795 [DEBUG] switch_rtp.c:7789 RTP RECV DTMF 4:400 2021-02-20 11:28:47.061795 [INFO] switch_channel.c:515 RECV DTMF 4:400 2021-02-20 11:28:47.461504 [DEBUG] switch_rtp.c:7789 RTP RECV DTMF 5:400 2021-02-20 11:28:47.461504 [INFO] switch_channel.c:515 RECV DTMF 5:400 2021-02-20 11:28:47.881346 [DEBUG] switch_rtp.c:7789 RTP RECV DTMF 0:400 2021-02-20 11:28:47.881346 [INFO] switch_channel.c:515 RECV DTMF 0:400 2021-02-20 11:28:48.281220 [DEBUG] switch_rtp.c:7789 RTP RECV DTMF 0:400 2021-02-20 11:28:48.281220 [INFO] switch_channel.c:515 RECV DTMF 0:400 2021-02-20 11:28:48.805572 [DEBUG] switch_rtp.c:7789 RTP RECV DTMF #:400 2021-02-20 11:28:48.805572 [INFO] switch_channel.c:515 RECV DTMF #:400 2021-02-20 11:29:04.881294 [NOTICE] sofia.c:1079 Hangup sofia/external/ nobody@192.168.1.71 [CS_EXECUTE] [NORMAL_CLEARING] -- Yet, they do arrive on the Freeswitch instances. I've attempted to add <action application="set" data="rtp_manual_rtp_bugs=ignore_dtmf_duration"/> to my inbound dialplan xml. I'm leaning toward these being a "weird" DTMF packet and not a FreeSWITCH issue, but I'm curious if anyone has encountered a similar problem, or has advice of what we could test on the FS side. -- Supporting Details: Test Environment: I took a packet capture from production and filtered it down to the A leg's RFC2833 packets, and saved this to a new file. I then used this pcap file in a SIPP UAC scenario which is acting as the A Leg. Freeswitch sits in the middle and I've configured it following this guide ( https://freeswitch.org/confluence/display/FREESWITCH/SBC+FreeSWITCH+Configur...) as a barebones SBC. Freeswitch is version 1.8.3 The B Leg is a simple pjsua client configured to answer an inbound call. -- Best Regards, KC