DTMF spuriously missed

uncleanon · November 16, 2018, 11:22am

I have a freepbx voip system which is connected to a goip-4 gsm gateway. The relevant freepbx configuration is:

host=dynamic
port=5060
context=from-trunk
insecure=port,invite
qualify=yes
secret=xxxxxx
type=peer
nat=no
canreinvite=no
defaultuser=goip-1
dtmfmode=rfc2833

99% of the time incoming calls which are routed to an IVR work correctly, however from time to time when the incoming calls are prompted to press 1 from the ivr this seems to be missed by the goip since looking at the asterisk log for one such call I can see:

/var/log/asterisk/full:[2018-11-16 10:49:35] VERBOSE[11051][C-00000181] pbx.c: Executing [[email protected]:10] Set("SIP/goip-1-000002ee", "TIMEOUT(digit)=3") in new stack
/var/log/asterisk/full:[2018-11-16 10:49:35] VERBOSE[11051][C-00000181] func_timeout.c: Digit timeout set to 3.000
/var/log/asterisk/full:[2018-11-16 10:49:35] VERBOSE[11051][C-00000181] pbx.c: Executing [[email protected]:11] ExecIf("SIP/goip-1-000002ee", "1?Background(custom/ivr-hello)") in new stack
/var/log/asterisk/full:[2018-11-16 10:49:35] VERBOSE[11051][C-00000181] file.c: <SIP/goip-1-000002ee> Playing 'custom/ivr-hello.slin' (language 'en')
/var/log/asterisk/full:[2018-11-16 10:49:41] VERBOSE[11051][C-00000181] pbx.c: Executing [[email protected]:12] WaitExten("SIP/goip-1-000002ee", "30,") in new stack
/var/log/asterisk/full:[2018-11-16 10:50:11] VERBOSE[11051][C-00000181] pbx_builtins.c: Timeout on SIP/goip-1-000002ee, going to 't'
/var/log/asterisk/full:[2018-11-16 10:50:11] VERBOSE[11051][C-00000181] pbx.c: Executing [[email protected]:1] Set("SIP/goip-1-000002ee", "TIMEOUT_LOOPCOUNT=1") in new stack
/var/log/asterisk/full:[2018-11-16 10:50:11] VERBOSE[11051][C-00000181] pbx.c: Executing [[email protected]:2] GotoIf("SIP/goip-1-000002ee", "0?final") in new stack
/var/log/asterisk/full:[2018-11-16 10:50:11] VERBOSE[11051][C-00000181] pbx.c: Executing [[email protected]:3] Set("SIP/goip-1-000002ee", "IVR_MSG=custom/ivr-hello") in new stack
/var/log/asterisk/full:[2018-11-16 10:50:11] VERBOSE[11051][C-00000181] pbx.c: Executing [[email protected]:4] Goto("SIP/goip-1-000002ee", "s,start") in new stack
/var/log/asterisk/full:[2018-11-16 10:50:11] VERBOSE[11051][C-00000181] pbx_builtins.c: Goto (ivr-1,s,10)
/var/log/asterisk/full:[2018-11-16 10:50:11] VERBOSE[11051][C-00000181] pbx.c: Executing [[email protected]:10] Set("SIP/goip-1-000002ee", "TIMEOUT(digit)=3") in new stack
/var/log/asterisk/full:[2018-11-16 10:50:11] VERBOSE[11051][C-00000181] func_timeout.c: Digit timeout set to 3.000
/var/log/asterisk/full:[2018-11-16 10:50:11] VERBOSE[11051][C-00000181] pbx.c: Executing [[email protected]:11] ExecIf("SIP/goip-1-000002ee", "1?Background(custom/ivr-hello)") in new stack
/var/log/asterisk/full:[2018-11-16 10:50:11] VERBOSE[11051][C-00000181] file.c: <SIP/goip-1-000002ee> Playing 'custom/ivr-hello.slin' (language 'en')
/var/log/asterisk/full:[2018-11-16 10:50:16] VERBOSE[11051][C-00000181] pbx.c: Executing [[email protected]:12] WaitExten("SIP/goip-1-000002ee", "30,") in new stack
/var/log/asterisk/full:[2018-11-16 10:50:46] VERBOSE[11051][C-00000181] pbx_builtins.c: Timeout on SIP/goip-1-000002ee, going to 't'
/var/log/asterisk/full:[2018-11-16 10:50:46] VERBOSE[11051][C-00000181] pbx.c: Executing [[email protected]:1] Set("SIP/goip-1-000002ee", "TIMEOUT_LOOPCOUNT=2") in new stack
/var/log/asterisk/full:[2018-11-16 10:50:46] VERBOSE[11051][C-00000181] pbx.c: Executing [[email protected]:2] GotoIf("SIP/goip-1-000002ee", "0?final") in new stack
/var/log/asterisk/full:[2018-11-16 10:50:46] VERBOSE[11051][C-00000181] pbx.c: Executing [[email protected]:3] Set("SIP/goip-1-000002ee", "IVR_MSG=custom/ivr-hello") in new stack
/var/log/asterisk/full:[2018-11-16 10:50:46] VERBOSE[11051][C-00000181] pbx.c: Executing [[email protected]:4] Goto("SIP/goip-1-000002ee", "s,start") in new stack
/var/log/asterisk/full:[2018-11-16 10:50:46] VERBOSE[11051][C-00000181] pbx_builtins.c: Goto (ivr-1,s,10)
/var/log/asterisk/full:[2018-11-16 10:50:46] VERBOSE[11051][C-00000181] pbx.c: Executing [[email protected]:10] Set("SIP/goip-1-000002ee", "TIMEOUT(digit)=3") in new stack
/var/log/asterisk/full:[2018-11-16 10:50:46] VERBOSE[11051][C-00000181] func_timeout.c: Digit timeout set to 3.000
/var/log/asterisk/full:[2018-11-16 10:50:46] VERBOSE[11051][C-00000181] pbx.c: Executing [[email protected]:11] ExecIf("SIP/goip-1-000002ee", "1?Background(custom/ivr-hello)") in new stack
/var/log/asterisk/full:[2018-11-16 10:50:46] VERBOSE[11051][C-00000181] file.c: <SIP/goip-1-000002ee> Playing 'custom/ivr-hello.slin' (language 'en')
/var/log/asterisk/full:[2018-11-16 10:50:52] VERBOSE[11051][C-00000181] pbx.c: Executing [[email protected]:12] WaitExten("SIP/goip-1-000002ee", "30,") in new stack
/var/log/asterisk/full:[2018-11-16 10:51:22] VERBOSE[11051][C-00000181] pbx_builtins.c: Timeout on SIP/goip-1-000002ee, going to 't'
/var/log/asterisk/full:[2018-11-16 10:51:22] VERBOSE[11051][C-00000181] pbx.c: Executing [[email protected]:1] Set("SIP/goip-1-000002ee", "TIMEOUT_LOOPCOUNT=3") in new stack
/var/log/asterisk/full:[2018-11-16 10:51:22] VERBOSE[11051][C-00000181] pbx.c: Executing [[email protected]:2] GotoIf("SIP/goip-1-000002ee", "1?final") in new stack
/var/log/asterisk/full:[2018-11-16 10:51:22] VERBOSE[11051][C-00000181] pbx_builtins.c: Goto (ivr-1,t,5)
/var/log/asterisk/full:[2018-11-16 10:51:22] VERBOSE[11051][C-00000181] pbx.c: Executing [[email protected]:5] Goto("SIP/goip-1-000002ee", "app-blackhole,hangup,1") in new stack
/var/log/asterisk/full:[2018-11-16 10:51:22] VERBOSE[11051][C-00000181] pbx_builtins.c: Goto (app-blackhole,hangup,1)

The GOIP’s dtmf signalling is set to “outband” and the “outband type” to rfc2833 as per the attached picture: goip%20config

So what can I do to further debug the issue, it seems that GOIP might have missed the DTMF hence is not really sending the required packet to asterisk and that’s why the ivr timesout. Since this issue occurs randomly I dunno if it is something to do with the goip, with the GSM that has actually dialed one of the goip’s numbers or asterisk is to blame.

stom · November 16, 2018, 12:03pm

How do you know that your user coming from gsm is actually pressing any digits?
Dtmf signaling on gsm networks is done outofband.

Any logs of the goip regarding dtmf?

uncleanon · November 16, 2018, 12:15pm

In this particular case the user was initially calling to the number1 of the goip (this particular model has 4 sim slots so 4 numbers). Then the user called in to number in slot 2 (which is routed the same way as number 1 to the IVR) and managed to press 1 and the call was successful. Regarding how I know the user is pressing one - on the second call the user said so

Unfortunately goip doesn’t seem to have any logging facility whatsoever.

BlazeStudios · November 16, 2018, 1:58pm

Change the DTMF Signaling to rfc2833

uncleanon · November 16, 2018, 3:14pm

But as you can see it’s set to rfc2833 everywhere.

stom · November 16, 2018, 6:12pm

Unfortunately there is a lot of misconfiguration as carriers migrate to voip.
It is very often the case, that the carrier negotiates dtmf as rfc2833, however the user cpe sends everything inband (you can hear it if you setup recording) but no rfc2833 message arrives
RFC2833 is very robust since it is a digital text message.
Nothing to configure, nothing to tune.
Your problem lies behind the goip device,and requires traces involving the gsm provider. And even then it could be another provider that has the real issue or just a misconfigured gateway. The reason that it doesn’t always happen is because calls aren’t routed via the same paths for load balancing and resilience reasons.
You have to make default ivr paths, with no digits.

Good luck

uncleanon · November 16, 2018, 6:15pm

The thing is currently freepbx (default settings) records only when a conversation is bridged to an agent. For example I don’t get recording with the IVR messages nor with what the user has input or might have said BEFORE being bridged to a real device.

stom · November 16, 2018, 6:50pm

Yes, that is true. However it can be changed if you do a couple of slight modifications in freepbx by hand.

Have a look here.
https://issues.freepbx.org/browse/FREEPBX-17866

system · November 23, 2018, 6:50pm

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