DTMF issues with S705 with VPN activated, works with in band audio (not recommended)

Sangoma Hardware Phones
1

Our FreePBX server sits on prem in the DMZ. We are deploying Sangoma S705 phones. Testing has gone well from the LAN and externally. When we put the phones in our small offices that have a site-to-site VPN we ran into problems with dead air. I ensured the correct ports were open but wasn’t able to resolve the issue and suspect possible translation related problem. I decided to try enabling the VPN server on FreePBX and configured those phones to connect via VPN, which fixed the problem.

I’ve now got some calls that staff aren’t able to call in to Gotomeetings using an access code. After some troubleshooting, I found that only the phones that are configured to use VPN have this problem. SangomaConnect soft phones and S705 phones that have the VPN turned off work just fine.

I changed the DTMF signaling on my extension to “in band audio (not recommended)” and tested successfully with and without the VPN. Am I okay to use that setting for my end users? Does anybody know if there’s a better way to address it?

Here’s a little bit of the log from one that didn’t work when using RFC4733 and VPN. This is just the first digit ‘8’ that I pressed:

[2021-11-17 10:18:23] DTMF[39509][C-0000147d]: channel.c:4010 __ast_read: DTMF begin ‘8’ received on PJSIP/5001-000013c9
[2021-11-17 10:18:23] DTMF[39509][C-0000147d]: channel.c:4021 __ast_read: DTMF begin passthrough ‘8’ on PJSIP/5001-000013c9
[2021-11-17 10:18:23] DTMF[39509][C-0000147d]: channel.c:3896 __ast_read: DTMF end ‘8’ received on PJSIP/5001-000013c9, duration 3 ms
[2021-11-17 10:18:23] DTMF[39509][C-0000147d]: channel.c:3947 __ast_read: DTMF end accepted with begin ‘8’ on PJSIP/5001-000013c9
[2021-11-17 10:18:23] DTMF[39509][C-0000147d]: channel.c:3962 __ast_read: DTMF end ‘8’ detected to have actual duration 11 on the wire, emulation will be triggered on PJSIP/5001-000013c9
[2021-11-17 10:18:23] DTMF[39509][C-0000147d]: channel.c:3969 __ast_read: DTMF end ‘8’ has duration 11 but want minimum 80, emulating on PJSIP/5001-000013c9
[2021-11-17 10:18:23] DTMF[39509][C-0000147d]: channel.c:4010 __ast_read: DTMF begin ‘8’ received on PJSIP/5001-000013c9
[2021-11-17 10:18:23] DTMF[39509][C-0000147d]: channel.c:4014 __ast_read: DTMF begin ignored ‘8’ on PJSIP/5001-000013c9
[2021-11-17 10:18:23] DTMF[39509][C-0000147d]: channel.c:3896 __ast_read: DTMF end ‘8’ received on PJSIP/5001-000013c9, duration 6 ms
[2021-11-17 10:18:23] DTMF[39509][C-0000147d]: channel.c:4044 __ast_read: DTMF end emulation of ‘8’ queued on PJSIP/5001-000013c9
[2021-11-17 10:18:23] DTMF[39509][C-0000147d]: channel.c:3896 __ast_read: DTMF end ‘8’ received on PJSIP/5001-000013c9, duration 6 ms
[2021-11-17 10:18:23] DTMF[39509][C-0000147d]: channel.c:3923 __ast_read: DTMF begin emulation of ‘8’ with duration 80 queued on PJSIP/5001-000013c9
[2021-11-17 10:18:23] DTMF[39509][C-0000147d]: channel.c:4010 __ast_read: DTMF begin ‘8’ received on PJSIP/5001-000013c9
[2021-11-17 10:18:23] DTMF[39509][C-0000147d]: channel.c:4014 __ast_read: DTMF begin ignored ‘8’ on PJSIP/5001-000013c9
[2021-11-17 10:18:23] DTMF[39509][C-0000147d]: channel.c:3896 __ast_read: DTMF end ‘8’ received on PJSIP/5001-000013c9, duration 10 ms
[2021-11-17 10:18:23] DTMF[39509][C-0000147d]: channel.c:4044 __ast_read: DTMF end emulation of ‘8’ queued on PJSIP/5001-000013c9
[2021-11-17 10:18:23] DTMF[39509][C-0000147d]: channel.c:3896 __ast_read: DTMF end ‘8’ received on PJSIP/5001-000013c9, duration 10 ms
[2021-11-17 10:18:23] DTMF[39509][C-0000147d]: channel.c:3923 __ast_read: DTMF begin emulation of ‘8’ with duration 80 queued on PJSIP/5001-000013c9
[2021-11-17 10:18:23] DTMF[39509][C-0000147d]: channel.c:4010 __ast_read: DTMF begin ‘8’ received on PJSIP/5001-000013c9
[2021-11-17 10:18:23] DTMF[39509][C-0000147d]: channel.c:4014 __ast_read: DTMF begin ignored ‘8’ on PJSIP/5001-000013c9
[2021-11-17 10:18:23] DTMF[39509][C-0000147d]: channel.c:3896 __ast_read: DTMF end ‘8’ received on PJSIP/5001-000013c9, duration 13 ms
[2021-11-17 10:18:23] DTMF[39509][C-0000147d]: channel.c:4044 __ast_read: DTMF end emulation of ‘8’ queued on PJSIP/5001-000013c9
[2021-11-17 10:18:23] DTMF[39509][C-0000147d]: channel.c:3896 __ast_read: DTMF end ‘8’ received on PJSIP/5001-000013c9, duration 13 ms
[2021-11-17 10:18:23] DTMF[39509][C-0000147d]: channel.c:3923 __ast_read: DTMF begin emulation of ‘8’ with duration 80 queued on PJSIP/5001-000013c9
[2021-11-17 10:18:23] DTMF[39509][C-0000147d]: channel.c:4010 __ast_read: DTMF begin ‘8’ received on PJSIP/5001-000013c9
[2021-11-17 10:18:23] DTMF[39509][C-0000147d]: channel.c:4014 __ast_read: DTMF begin ignored ‘8’ on PJSIP/5001-000013c9
[2021-11-17 10:18:23] DTMF[39509][C-0000147d]: channel.c:3896 __ast_read: DTMF end ‘8’ received on PJSIP/5001-000013c9, duration 16 ms
[2021-11-17 10:18:23] DTMF[39509][C-0000147d]: channel.c:4044 __ast_read: DTMF end emulation of ‘8’ queued on PJSIP/5001-000013c9
[2021-11-17 10:18:23] DTMF[39509][C-0000147d]: channel.c:3896 __ast_read: DTMF end ‘8’ received on PJSIP/5001-000013c9, duration 16 ms
[2021-11-17 10:18:23] DTMF[39509][C-0000147d]: channel.c:3923 __ast_read: DTMF begin emulation of ‘8’ with duration 80 queued on PJSIP/5001-000013c9
[2021-11-17 10:18:23] DTMF[39509][C-0000147d]: channel.c:4010 __ast_read: DTMF begin ‘8’ received on PJSIP/5001-000013c9
[2021-11-17 10:18:23] DTMF[39509][C-0000147d]: channel.c:4014 __ast_read: DTMF begin ignored ‘8’ on PJSIP/5001-000013c9
[2021-11-17 10:18:23] DTMF[39509][C-0000147d]: channel.c:3896 __ast_read: DTMF end ‘8’ received on PJSIP/5001-000013c9, duration 18 ms
[2021-11-17 10:18:23] DTMF[39509][C-0000147d]: channel.c:4044 __ast_read: DTMF end emulation of ‘8’ queued on PJSIP/5001-000013c9
[2021-11-17 10:18:23] DTMF[39509][C-0000147d]: channel.c:3896 __ast_read: DTMF end ‘8’ received on PJSIP/5001-000013c9, duration 18 ms
[2021-11-17 10:18:23] DTMF[39509][C-0000147d]: channel.c:3923 __ast_read: DTMF begin emulation of ‘8’ with duration 80 queued on PJSIP/5001-000013c9
[2021-11-17 10:18:23] DTMF[39509][C-0000147d]: channel.c:3896 __ast_read: DTMF end ‘8’ received on PJSIP/5001-000013c9, duration 18 ms
[2021-11-17 10:18:24] DTMF[39509][C-0000147d]: channel.c:4044 __ast_read: DTMF end emulation of ‘8’ queued on PJSIP/5001-000013c9
[2021-11-17 10:18:24] DTMF[39509][C-0000147d]: channel.c:3896 __ast_read: DTMF end ‘8’ received on PJSIP/5001-000013c9, duration 18 ms
[2021-11-17 10:18:24] DTMF[39509][C-0000147d]: channel.c:3923 __ast_read: DTMF begin emulation of ‘8’ with duration 80 queued on PJSIP/5001-000013c9

Here are logs for one that did work when using RFC4733 without VPN:

[2021-11-17 10:22:03] DTMF[46201][C-0000147f]: channel.c:3896 __ast_read: DTMF end ‘8’ received on PJSIP/5001-000013cc, duration 250 ms
[2021-11-17 10:22:03] DTMF[46201][C-0000147f]: channel.c:3923 __ast_read: DTMF begin emulation of ‘8’ with duration 250 queued on PJSIP/5001-000013cc
[2021-11-17 10:22:03] DTMF[46201][C-0000147f]: channel.c:4102 __ast_read: DTMF end emulation of ‘8’ queued on PJSIP/5001-000013cc
[2021-11-17 10:22:03] DTMF[46201][C-0000147f]: channel.c:3896 __ast_read: DTMF end ‘9’ received on PJSIP/5001-000013cc, duration 250 ms
[2021-11-17 10:22:03] DTMF[46201][C-0000147f]: channel.c:3923 __ast_read: DTMF begin emulation of ‘9’ with duration 250 queued on PJSIP/5001-000013cc
[2021-11-17 10:22:04] DTMF[46201][C-0000147f]: channel.c:4044 __ast_read: DTMF end emulation of ‘9’ queued on PJSIP/5001-000013cc
[2021-11-17 10:22:04] DTMF[46201][C-0000147f]: channel.c:3896 __ast_read: DTMF end ‘2’ received on PJSIP/5001-000013cc, duration 250 ms
[2021-11-17 10:22:04] DTMF[46201][C-0000147f]: channel.c:3923 __ast_read: DTMF begin emulation of ‘2’ with duration 250 queued on PJSIP/5001-000013cc
[2021-11-17 10:22:04] DTMF[46201][C-0000147f]: channel.c:4044 __ast_read: DTMF end emulation of ‘2’ queued on PJSIP/5001-000013cc
[2021-11-17 10:22:05] DTMF[46201][C-0000147f]: channel.c:3896 __ast_read: DTMF end ‘0’ received on PJSIP/5001-000013cc, duration 250 ms
[2021-11-17 10:22:05] DTMF[46201][C-0000147f]: channel.c:3923 __ast_read: DTMF begin emulation of ‘0’ with duration 250 queued on PJSIP/5001-000013cc
[2021-11-17 10:22:05] DTMF[46201][C-0000147f]: channel.c:4102 __ast_read: DTMF end emulation of ‘0’ queued on PJSIP/5001-000013cc
[2021-11-17 10:22:05] DTMF[46201][C-0000147f]: channel.c:3896 __ast_read: DTMF end ‘2’ received on PJSIP/5001-000013cc, duration 250 ms
[2021-11-17 10:22:05] DTMF[46201][C-0000147f]: channel.c:3923 __ast_read: DTMF begin emulation of ‘2’ with duration 250 queued on PJSIP/5001-000013cc
[2021-11-17 10:22:06] DTMF[46201][C-0000147f]: channel.c:4102 __ast_read: DTMF end emulation of ‘2’ queued on PJSIP/5001-000013cc
[2021-11-17 10:22:06] DTMF[46201][C-0000147f]: channel.c:3896 __ast_read: DTMF end ‘5’ received on PJSIP/5001-000013cc, duration 250 ms
[2021-11-17 10:22:06] DTMF[46201][C-0000147f]: channel.c:3923 __ast_read: DTMF begin emulation of ‘5’ with duration 250 queued on PJSIP/5001-000013cc
[2021-11-17 10:22:06] DTMF[46201][C-0000147f]: channel.c:4044 __ast_read: DTMF end emulation of ‘5’ queued on PJSIP/5001-000013cc
[2021-11-17 10:22:08] DTMF[46201][C-0000147f]: channel.c:3896 __ast_read: DTMF end ‘7’ received on PJSIP/5001-000013cc, duration 250 ms
[2021-11-17 10:22:08] DTMF[46201][C-0000147f]: channel.c:3923 __ast_read: DTMF begin emulation of ‘7’ with duration 250 queued on PJSIP/5001-000013cc
[2021-11-17 10:22:08] DTMF[46201][C-0000147f]: channel.c:4102 __ast_read: DTMF end emulation of ‘7’ queued on PJSIP/5001-000013cc
[2021-11-17 10:22:08] DTMF[46201][C-0000147f]: channel.c:3896 __ast_read: DTMF end ‘4’ received on PJSIP/5001-000013cc, duration 250 ms
[2021-11-17 10:22:08] DTMF[46201][C-0000147f]: channel.c:3923 __ast_read: DTMF begin emulation of ‘4’ with duration 250 queued on PJSIP/5001-000013cc
[2021-11-17 10:22:08] DTMF[46201][C-0000147f]: channel.c:4102 __ast_read: DTMF end emulation of ‘4’ queued on PJSIP/5001-000013cc
[2021-11-17 10:22:09] DTMF[46201][C-0000147f]: channel.c:3896 __ast_read: DTMF end ‘1’ received on PJSIP/5001-000013cc, duration 250 ms
[2021-11-17 10:22:09] DTMF[46201][C-0000147f]: channel.c:3923 __ast_read: DTMF begin emulation of ‘1’ with duration 250 queued on PJSIP/5001-000013cc
[2021-11-17 10:22:09] DTMF[46201][C-0000147f]: channel.c:4102 __ast_read: DTMF end emulation of ‘1’ queued on PJSIP/5001-000013cc
[2021-11-17 10:22:09] DTMF[46201][C-0000147f]: channel.c:3896 __ast_read: DTMF end ‘#’ received on PJSIP/5001-000013cc, duration 250 ms
[2021-11-17 10:22:09] DTMF[46201][C-0000147f]: channel.c:3923 __ast_read: DTMF begin emulation of ‘#’ with duration 250 queued on PJSIP/5001-000013cc
[2021-11-17 10:22:10] DTMF[46201][C-0000147f]: channel.c:4102 __ast_read: DTMF end emulation of ‘#’ queued on PJSIP/5001-000013cc

2

Is your VPN, by any chance, operating over a TCP channel?

3

Thanks for the reply.

It’s configured on UDP 1194.

4

Basically, it thinks the digits are far too short. I was thinking that was because the begin and end were being delayed and put in the same packet. However, even if that happened, the duration should be taken from information in the packets.

I cannot think of how a VPN would mangle things that way, but there is a segmentation feature in RFC 4733, and it is possible that this is being used inappropriately and also possible that Asterisk doesn’t support it. I note that the working case is only sending END frames, but the broken one is sending both.

You really need the full, decrypted, packets. I’m not sure that even rtp debug provides that level of information, although they should appear unencrypted within the Asterisk box, so sngrep/tcpdump/wireshark should be usable, in some combination. Ideally, you also need millisecond timestamps, which an be enabled in logger.conf, but I’m not sure that FreePBX permits you to do that.

5

To decode traffic in current SSL/TLS ?deployments, compile and install

and give it your service key for the -k option of the traffic/protocol you are investigating. It comes with a man page

(Hint, Stick with RSA :wink: )

6

This topic was automatically closed 31 days after the last reply. New replies are no longer allowed.