Extra touch/DTMF tones when dialing out

We migrated our FreePBX distro version 5.211.65-14 at the beginning of January from:

  • From a regular Celeron hardware with an older Digium PCI 4-port FXO card

  • To a virtual machine running on Hyper-V, the PSTN lines are connect using a networked GXW410X
    PSTN Gateway.

Initially we had a problem with outgoing calls being dropped at exactly 15 minutes of duration. A firmware upgrade on the GXW4104 corrected that.

But another problem has been a bit harder to solve. On outgoing calls, after dialing the number and just before the destination starts ringing we hear two additional, rather sharp DTMF tones.

On some calls this is not an issue, but on others it seems when the destination picks up it hears some part of the additional tones. For example calling a conferencing service when it first answers it says “You’ve entered an invalid meeting ID”. You can usually then enter the correct id - but sometimes need to redial.

This happens without fail on all of the in-office phones that are connected via ATA (either old Sipura/Linksys/Cisco versions).

If I use a 3CX softphone from my home-office the extra tones do not occur.

We’ve reported this to Grandstream, they loaded our config on a GXW4104 in their lab and cannot re-create the problem. So far they are stumped, as we are.

Any ideas on what this might be or how to better track it down.

Thank you - Richard.

BTW, in case anyone is wondering why we went the VM route - it was for failover and disaster recovery. We run both our pfSense router/firewall and FreePBX as VM’s on the same 1U rack server. Maxed out with RAID1 SSD’s and 16GB of ram, It’s less than $1000. We use Hyper-V’s replication to mirror it to a second identical server. Here’s the hardware we’re using:

If you use any form of virtualization, you will need a robust dahdi working to support conferences and other audio functionality, Until

dahdi_test -vv

returns consistent +99.8% results, you are likely SOL :wink:

Thanks for the heads up on that. I think we are looking OK:

[[email protected] etc]# dahdi_test -vv
Opened pseudo dahdi interface, measuring accuracy...

8192 samples in 8197.033 system clock sample intervals (99.939%)
8192 samples in 8190.096 system clock sample intervals (99.977%)
8192 samples in 8173.184 system clock sample intervals (99.770%)
8192 samples in 8196.535 system clock sample intervals (99.945%)
8192 samples in 8196.816 system clock sample intervals (99.941%)
8192 samples in 8172.887 system clock sample intervals (99.767%)
8192 samples in 8196.896 system clock sample intervals (99.940%)
8192 samples in 8196.808 system clock sample intervals (99.941%)
8192 samples in 8204.888 system clock sample intervals (99.843%)
8192 samples in 8180.873 system clock sample intervals (99.864%)
8192 samples in 8204.824 system clock sample intervals (99.843%)^C
--- Results after 11 passes ---
Best: 99.977% -- Worst: 99.767% -- Average: 99.888184%
Cummulative Accuracy (not per pass): 99.999
[[email protected] etc]#

The big issue so far is just the extra DTMF tones.

I would suspect that those DTMF’s are coming from your GXW410X’s configuration there is nothing in FreePBX/Asterisk that would do that, you could add DTMF to your “full” log file options to check .

Thanks - that did the trick.

The log now clearly (DTMF shows up in caps), at least to my untrained eye, shows the DTMF tones being received from the channels on the Grandstream.

Now here’s hoping they can figure out how to fix this.

Or am I missing something? I’ve included the log below (had to chop off some to meet size limit). I did replace change the source # for privacy, but the target number is GoToMeetings public conference number.

Thank you again - Richard
[2015-02-03 07:46:09] VERBOSE[48935][C-000002a7] pbx.c: – Executing [[email protected]:13] Set(“SIP/1062-00000079”, “OUTNUM=18773092073”) in new stack
[2015-02-03 07:46:09] VERBOSE[48935][C-000002a7] pbx.c: – Executing [[email protected]:13] Set(“SIP/1062-00000079”, “OUTNUM=18773092073”) in new stack
[2015-02-03 07:46:09] VERBOSE[48935][C-000002a7] pbx.c: – Executing [[email protected]:14] Set(“SIP/1062-00000079”, “custom=SIP/PSTN1_4806414002”) in new stack
[2015-02-03 07:46:09] VERBOSE[48935][C-000002a7] pbx.c: – Executing [[email protected]:14] Set(“SIP/1062-00000079”, “custom=SIP/PSTN1_4806414002”) in new stack
[2015-02-03 07:46:09] VERBOSE[48935][C-000002a7] pbx.c: – Executing [[email protected]:15] ExecIf(“SIP/1062-00000079”, “0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default))”) in new stack
[2015-02-03 07:46:09] VERBOSE[48935][C-000002a7] pbx.c: – Executing [[email protected]:15] ExecIf(“SIP/1062-00000079”, “0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default))”) in new stack
[2015-02-03 07:46:09] VERBOSE[48935][C-000002a7] pbx.c: – Executing [[email protected]:16] ExecIf(“SIP/1062-00000079”, “0?Set(DIAL_TRUNK_OPTIONS=M(confirm))”) in new stack
[2015-02-03 07:46:09] VERBOSE[48935][C-000002a7] pbx.c: – Executing [[email protected]:16] ExecIf(“SIP/1062-00000079”, “0?Set(DIAL_TRUNK_OPTIONS=M(confirm))”) in new stack
[2015-02-03 07:46:09] VERBOSE[48935][C-000002a7] pbx.c: – Executing [[email protected]:17] Macro(“SIP/1062-00000079”, “dialout-trunk-predial-hook,”) in new stack
[2015-02-03 07:46:09] VERBOSE[48935][C-000002a7] pbx.c: – Executing [[email protected]:17] Macro(“SIP/1062-00000079”, “dialout-trunk-predial-hook,”) in new stack
[2015-02-03 07:46:09] VERBOSE[48935][C-000002a7] pbx.c: – Executing [[email protected]:1] MacroExit(“SIP/1062-00000079”, “”) in new stack
[2015-02-03 07:46:09] VERBOSE[48935][C-000002a7] pbx.c: – Executing [[email protected]:1] MacroExit(“SIP/1062-00000079”, “”) in new stack
[2015-02-03 07:46:09] VERBOSE[48935][C-000002a7] pbx.c: – Executing [[email protected]:18] GotoIf(“SIP/1062-00000079”, “0?bypass,1”) in new stack
[2015-02-03 07:46:09] VERBOSE[48935][C-000002a7] pbx.c: – Executing [[email protected]:18] GotoIf(“SIP/1062-00000079”, “0?bypass,1”) in new stack
[2015-02-03 07:46:09] VERBOSE[48935][C-000002a7] pbx.c: – Executing [[email protected]:19] ExecIf(“SIP/1062-00000079”, “1?Set(CONNECTEDLINE(num,i)=18773092073)”) in new stack
[2015-02-03 07:46:09] VERBOSE[48935][C-000002a7] pbx.c: – Executing [[email protected]:19] ExecIf(“SIP/1062-00000079”, “1?Set(CONNECTEDLINE(num,i)=18773092073)”) in new stack
[2015-02-03 07:46:09] VERBOSE[48935][C-000002a7] pbx.c: – Executing [[email protected]:20] ExecIf(“SIP/1062-00000079”, “1?Set(CONNECTEDLINE(name,i)=CID:4806414002)”) in new stack
[2015-02-03 07:46:09] VERBOSE[48935][C-000002a7] pbx.c: – Executing [[email protected]:20] ExecIf(“SIP/1062-00000079”, “1?Set(CONNECTEDLINE(name,i)=CID:4806414002)”) in new stack
[2015-02-03 07:46:09] VERBOSE[48935][C-000002a7] pbx.c: – Executing [[email protected]:21] GotoIf(“SIP/1062-00000079”, “0?customtrunk”) in new stack
[2015-02-03 07:46:09] VERBOSE[48935][C-000002a7] pbx.c: – Executing [[email protected]:21] GotoIf(“SIP/1062-00000079”, “0?customtrunk”) in new stack
[2015-02-03 07:46:09] VERBOSE[48935][C-000002a7] pbx.c: – Executing [[email protected]:22] Dial(“SIP/1062-00000079”, “SIP/PSTN1_4806414002/18773092073,300,”) in new stack
[2015-02-03 07:46:09] VERBOSE[48935][C-000002a7] pbx.c: – Executing [[email protected]:22] Dial(“SIP/1062-00000079”, “SIP/PSTN1_4806414002/18773092073,300,”) in new stack
[2015-02-03 07:46:09] VERBOSE[48935][C-000002a7] netsock2.c: == Using SIP RTP TOS bits 184
[2015-02-03 07:46:09] VERBOSE[48935][C-000002a7] netsock2.c: == Using SIP RTP TOS bits 184
[2015-02-03 07:46:09] VERBOSE[48935][C-000002a7] netsock2.c: == Using SIP RTP CoS mark 5
[2015-02-03 07:46:09] VERBOSE[48935][C-000002a7] netsock2.c: == Using SIP RTP CoS mark 5
[2015-02-03 07:46:09] VERBOSE[48935][C-000002a7] app_dial.c: – Called SIP/PSTN1_4806414002/18773092073
[2015-02-03 07:46:09] VERBOSE[48935][C-000002a7] app_dial.c: – Called SIP/PSTN1_4806414002/18773092073
[2015-02-03 07:46:15] VERBOSE[48935][C-000002a7] app_dial.c: – SIP/PSTN1_4806414002-0000007a is ringing
[2015-02-03 07:46:15] VERBOSE[48935][C-000002a7] app_dial.c: – SIP/PSTN1_4806414002-0000007a is ringing
[2015-02-03 07:46:19] VERBOSE[48935][C-000002a7] app_dial.c: – SIP/PSTN1_4806414002-0000007a answered SIP/1062-00000079
[2015-02-03 07:46:19] VERBOSE[48935][C-000002a7] app_dial.c: – SIP/PSTN1_4806414002-0000007a answered SIP/1062-00000079
[2015-02-03 07:46:19] DTMF[48935][C-000002a7] channel.c: DTMF begin ‘7’ received on SIP/PSTN1_4806414002-0000007a
[2015-02-03 07:46:19] DTMF[48935][C-000002a7] channel.c: DTMF begin passthrough ‘7’ on SIP/PSTN1_4806414002-0000007a
[2015-02-03 07:46:19] DTMF[48935][C-000002a7] channel.c: DTMF end ‘7’ received on SIP/PSTN1_4806414002-0000007a, duration 100 ms
[2015-02-03 07:46:19] DTMF[48935][C-000002a7] channel.c: DTMF end accepted with begin ‘7’ on SIP/PSTN1_4806414002-0000007a
[2015-02-03 07:46:19] DTMF[48935][C-000002a7] channel.c: DTMF end ‘7’ detected to have actual duration 22 on the wire, emulation will be triggered on SIP/PSTN1_4806414002-0000007a
[2015-02-03 07:46:19] DTMF[48935][C-000002a7] channel.c: DTMF end ‘7’ has duration 22 but want minimum 80, emulating on SIP/PSTN1_4806414002-0000007a
[2015-02-03 07:46:19] DTMF[48935][C-000002a7] channel.c: DTMF begin ‘0’ received on SIP/PSTN1_4806414002-0000007a
[2015-02-03 07:46:19] DTMF[48935][C-000002a7] channel.c: DTMF begin ignored ‘0’ on SIP/PSTN1_4806414002-0000007a
[2015-02-03 07:46:19] DTMF[48935][C-000002a7] channel.c: DTMF end ‘0’ received on SIP/PSTN1_4806414002-0000007a, duration 100 ms
[2015-02-03 07:46:19] DTMF[48935][C-000002a7] channel.c: DTMF end emulation of ‘7’ queued on SIP/PSTN1_4806414002-0000007a
[2015-02-03 07:46:20] DTMF[48935][C-000002a7] channel.c: DTMF end ‘0’ received on SIP/PSTN1_4806414002-0000007a, duration 100 ms
[2015-02-03 07:46:20] DTMF[48935][C-000002a7] channel.c: DTMF begin emulation of ‘0’ with duration 100 queued on SIP/PSTN1_4806414002-0000007a
[2015-02-03 07:46:20] DTMF[48935][C-000002a7] channel.c: DTMF begin ‘0’ received on SIP/PSTN1_4806414002-0000007a
[2015-02-03 07:46:20] DTMF[48935][C-000002a7] channel.c: DTMF begin ignored ‘0’ on SIP/PSTN1_4806414002-0000007a
[2015-02-03 07:46:20] DTMF[48935][C-000002a7] channel.c: DTMF end ‘0’ received on SIP/PSTN1_4806414002-0000007a, duration 100 ms
[2015-02-03 07:46:20] DTMF[48935][C-000002a7] channel.c: DTMF end emulation of ‘0’ queued on SIP/PSTN1_4806414002-0000007a
[2015-02-03 07:46:20] DTMF[48935][C-000002a7] channel.c: DTMF end ‘0’ received on SIP/PSTN1_4806414002-0000007a, duration 100 ms
[2015-02-03 07:46:20] DTMF[48935][C-000002a7] channel.c: DTMF begin emulation of ‘0’ with duration 100 queued on SIP/PSTN1_4806414002-0000007a
[2015-02-03 07:46:20] DTMF[48935][C-000002a7] channel.c: DTMF end emulation of ‘0’ queued on SIP/PSTN1_4806414002-0000007a
[2015-02-03 07:46:23] VERBOSE[48935][C-000002a7] pbx.c: – Executing [[email protected]:1] Macro(“SIP/1062-00000079”, “hangupcall,”) in new stack
[2015-02-03 07:46:23] VERBOSE[48935][C-000002a7] pbx.c: – Executing [[email protected]:1] Macro(“SIP/1062-00000079”, “hangupcall,”) in new stack
[2015-02-03 07:46:23] VERBOSE[48935][C-000002a7] pbx.c: – Executing [[email protected]:1] GotoIf(“SIP/1062-00000079”, “1?theend”) in new stack
[2015-02-03 07:46:23] VERBOSE[48935][C-000002a7] pbx.c: – Executing [[email protected]:1] GotoIf(“SIP/1062-00000079”, “1?theend”) in new stack
[2015-02-03 07:46:23] VERBOSE[48935][C-000002a7] pbx.c: – Goto (macro-hangupcall,s,3)
[2015-02-03 07:46:23] VERBOSE[48935][C-000002a7] pbx.c: – Goto (macro-hangupcall,s,3)
[2015-02-03 07:46:23] VERBOSE[48935][C-000002a7] pbx.c: – Executing [[email protected]:3] ExecIf(“SIP/1062-00000079”, “0?Set(CDR(recordingfile)=)”) in new stack
[2015-02-03 07:46:23] VERBOSE[48935][C-000002a7] pbx.c: – Executing [[email protected]:3] ExecIf(“SIP/1062-00000079”, “0?Set(CDR(recordingfile)=)”) in new stack
[2015-02-03 07:46:23] VERBOSE[48935][C-000002a7] pbx.c: – Executing [[email protected]:4] Hangup(“SIP/1062-00000079”, “”) in new stack
[2015-02-03 07:46:23] VERBOSE[48935][C-000002a7] pbx.c: – Executing [[email protected]:4] Hangup(“SIP/1062-00000079”, “”) in new stack
[2015-02-03 07:46:23] VERBOSE[48935][C-000002a7] app_macro.c: == Spawn extension (macro-hangupcall, s, 4) exited non-zero on ‘SIP/1062-00000079’ in macro ‘hangupcall’
[2015-02-03 07:46:23] VERBOSE[48935][C-000002a7] app_macro.c: == Spawn extension (macro-hangupcall, s, 4) exited non-zero on ‘SIP/1062-00000079’ in macro ‘hangupcall’

Yes your gateway apparently dialed 700 on your channel, who knows why ? :wink: (two stage dialing maybe? )

I’ve been working with GrandStream support off an on for a while - no luck yet.

But playing around with the DTMF settings to be sure they match between FreePBX and the GrandStream.

OK, I finally made some progress on this - but not sure I understand why.

During testing today changing the ATA and the extension to both use “SIP Info” seems (so far) to have eliminated the extra dial tones.

Here’s how things are linked DTMF-wise (pardon the stick drawings):

Cordless phone via RJ11 to ATA
|
|
V
ATA - "DTMF Tx Method": SIP Info
|
|
V
Asterisk/FreePBX extensions "dtmfmode": SIP Info (application/dtmf)
|
|
V
Asterisk/FreePBX trunk definition for GXW4104: dtmfmode=rfc2833 (4 trunks defined this way)
|
|
V
GXW4104 Settings->SIP Channel Settings: DTMF Methods(1-7): ch1-4:2; (RFC2833)

I guess it sort of makes sense that the DTMF settings for the handeset to PBX link can be different than the DTMF settings for the PBX to GXW4104.

But would love to understand why using ATA/extension DTMF settings of either “In Band” or “RFC2833” caused the GrandStream gateway to inject the additional tones.

Any ideas?

Still plowing through this. The problem does not seem to happen on every single outgoing call - but it does happen regularly.

Of am I completely misreading the Asterisk logs. Here are two examples - the first works fine, the second has the problem.

Call #1 - Extra DTMF NOT received from GXW4104 (SIP/PSTN2_6026917239) when call answered, then I use keys to enter “963” which I see in the log as expected coming from SIP/1051-0000005a.

    2015-03-13 13:12:27] VERBOSE[3046][C-000003fe] netsock2.c:   == Using SIP RTP TOS bits 184
    2015-03-13 13:12:27] VERBOSE[3046][C-000003fe] netsock2.c:   == Using SIP RTP CoS mark 5
    2015-03-13 13:12:27] VERBOSE[3046][C-000003fe] app_dial.c:     -- Called SIP/PSTN2_6026917239/18773092073
    2015-03-13 13:12:30] VERBOSE[3046][C-000003fe] app_dial.c:     -- SIP/PSTN2_6026917239-0000005b is ringing
    2015-03-13 13:12:34] VERBOSE[3046][C-000003fe] app_dial.c:     -- SIP/PSTN2_6026917239-0000005b answered SIP/1051-0000005a
    2015-03-13 13:12:42] DTMF[3046][C-000003fe] channel.c: DTMF end '9' received on SIP/1051-0000005a, duration 250 ms
    2015-03-13 13:12:42] DTMF[3046][C-000003fe] channel.c: DTMF begin emulation of '9' with duration 250 queued on SIP/1051-0000005a
    2015-03-13 13:12:43] DTMF[3046][C-000003fe] channel.c: DTMF end emulation of '9' queued on SIP/1051-0000005a
    2015-03-13 13:12:43] DTMF[3046][C-000003fe] channel.c: DTMF end '6' received on SIP/1051-0000005a, duration 250 ms
    2015-03-13 13:12:43] DTMF[3046][C-000003fe] channel.c: DTMF begin emulation of '6' with duration 250 queued on SIP/1051-0000005a
    2015-03-13 13:12:43] DTMF[3046][C-000003fe] channel.c: DTMF end emulation of '6' queued on SIP/1051-0000005a
    2015-03-13 13:12:43] DTMF[3046][C-000003fe] channel.c: DTMF end '3' received on SIP/1051-0000005a, duration 250 ms
    2015-03-13 13:12:43] DTMF[3046][C-000003fe] channel.c: DTMF begin emulation of '3' with duration 250 queued on SIP/1051-0000005a
    2015-03-13 13:12:44] DTMF[3046][C-000003fe] channel.c: DTMF end emulation of '3' queued on SIP/1051-0000005a
    2015-03-13 13:12:44] DTMF[3046][C-000003fe] channel.c: DTMF end '#' received on SIP/1051-0000005a, duration 250 ms
    2015-03-13 13:12:44] DTMF[3046][C-000003fe] channel.c: DTMF begin emulation of '#' with duration 250 queued on SIP/1051-0000005a
    2015-03-13 13:12:45] DTMF[3046][C-000003fe] channel.c: DTMF end emulation of '#' queued on SIP/1051-0000005a
    2015-03-13 13:12:51] VERBOSE[3046][C-000003fe] pbx.c:     -- Executing [[email protected]:1] Macro("SIP/1051-0000005a", "hangupcall,") in new stack

Called #2 - Extra DTMF “7” received from GXW4104 (SIP/PSTN2_6026917239) when call answered, then I use keys to enter “963” which I see in the log as expected coming from SIP/1051-0000005e.

    2015-03-13 13:14:44] VERBOSE[3222][C-00000402] netsock2.c:   == Using SIP RTP TOS bits 184
    2015-03-13 13:14:44] VERBOSE[3222][C-00000402] netsock2.c:   == Using SIP RTP CoS mark 5
    2015-03-13 13:14:44] VERBOSE[3222][C-00000402] app_dial.c:     -- Called SIP/PSTN2_6026917239/18773092073
    2015-03-13 13:14:47] VERBOSE[3222][C-00000402] app_dial.c:     -- SIP/PSTN2_6026917239-0000005f is ringing
    2015-03-13 13:14:52] VERBOSE[3222][C-00000402] app_dial.c:     -- SIP/PSTN2_6026917239-0000005f answered SIP/1051-0000005e
    2015-03-13 13:14:52] DTMF[3222][C-00000402] channel.c: DTMF begin '7' received on SIP/PSTN2_6026917239-0000005f
    2015-03-13 13:14:52] DTMF[3222][C-00000402] channel.c: DTMF begin ignored '7' on SIP/PSTN2_6026917239-0000005f
    2015-03-13 13:14:52] DTMF[3222][C-00000402] channel.c: DTMF end '7' received on SIP/PSTN2_6026917239-0000005f, duration 100 ms
    2015-03-13 13:14:52] DTMF[3222][C-00000402] channel.c: DTMF end passthrough '7' on SIP/PSTN2_6026917239-0000005f
    2015-03-13 13:15:00] DTMF[3222][C-00000402] channel.c: DTMF end '9' received on SIP/1051-0000005e, duration 250 ms
    2015-03-13 13:15:00] DTMF[3222][C-00000402] channel.c: DTMF begin emulation of '9' with duration 250 queued on SIP/1051-0000005e
    2015-03-13 13:15:00] DTMF[3222][C-00000402] channel.c: DTMF end emulation of '9' queued on SIP/1051-0000005e
    2015-03-13 13:15:00] DTMF[3222][C-00000402] channel.c: DTMF end '6' received on SIP/1051-0000005e, duration 250 ms
    2015-03-13 13:15:00] DTMF[3222][C-00000402] channel.c: DTMF begin emulation of '6' with duration 250 queued on SIP/1051-0000005e
    2015-03-13 13:15:00] DTMF[3222][C-00000402] channel.c: DTMF end emulation of '6' queued on SIP/1051-0000005e
    2015-03-13 13:15:01] DTMF[3222][C-00000402] channel.c: DTMF end '3' received on SIP/1051-0000005e, duration 250 ms
    2015-03-13 13:15:01] DTMF[3222][C-00000402] channel.c: DTMF begin emulation of '3' with duration 250 queued on SIP/1051-0000005e
    2015-03-13 13:15:01] DTMF[3222][C-00000402] channel.c: DTMF end emulation of '3' queued on SIP/1051-0000005e
    2015-03-13 13:15:02] DTMF[3222][C-00000402] channel.c: DTMF end '#' received on SIP/1051-0000005e, duration 250 ms
    2015-03-13 13:15:02] DTMF[3222][C-00000402] channel.c: DTMF begin emulation of '#' with duration 250 queued on SIP/1051-0000005e
    2015-03-13 13:15:02] DTMF[3222][C-00000402] channel.c: DTMF end emulation of '#' queued on SIP/1051-0000005e
    2015-03-13 13:15:06] VERBOSE[3222][C-00000402] pbx.c:     -- Executing [[email protected]:1] Macro("SIP/1051-0000005e", "hangupcall,") in new stack

I can make a dozen calls and it seems this happens about half the time.

GrandStream’s ability to work on this is about nil. I’m supposed to get a senior tech to work on this next week - but I’m not that hopeful at this point.

The vendor I bought these from, TelephonyDepot, has been slow to start but they are trying to recreate the problem in their lab.

Any and all ideas are appreciated. Does anyone recommend a different gateway?

Thank you - Richard