DTMF Not recognized, not hanging up

rnrstar · July 9, 2020, 4:49pm

Installing a UC 40 running FreePBX 13.0.197.22 and I’m installing it behind a Cisco Meraki MX64 router. This is the first time I’ve used this type of router so I’m not sure if I’m running into a limitation of the router or it’s maybe something else.

Symptoms:

When dialing into an IVR it doesn’t recognize any digit press. I can hit 3 all day long and nothing happens. Eventually I get the no valid input message.
When I call out to my cell phone it works fine, I can talk both ways and the call lasts longer than 30 seconds. However, when I hang up on the FreePBX side, it doesn’t hang up on my cell phone.
When I call some numbers it appears to connect but I don’t ever hear any audio from the other end. Twilio logs shows that the call is connected.

We are using Twilio for our SIP provider. I have the trunks set to use RFC 4733 for DTMF mode. I’ve tried all the other settings like inband, out-of-band, and info all with the same results.

When I look at the log file I don’t see any digits being pressed. Here is the log for one of the call attempts:

[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [+17022976605@from-pstn-e164-us:1] Goto(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “from-pstn,7022976605,1”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx_builtins.c: Goto (from-pstn,7022976605,1)
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [7022976605@from-pstn:1] Set(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “__DIRECTION=INBOUND”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [7022976605@from-pstn:2] Gosub(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “sub-record-check,s,1(in,7022976605,dontcare)”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [s@sub-record-check:1] GotoIf(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “0?initialized”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [s@sub-record-check:2] Set(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “__REC_STATUS=INITIALIZED”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [s@sub-record-check:3] Set(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “NOW=1594312419”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [s@sub-record-check:4] Set(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “__DAY=09”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [s@sub-record-check:5] Set(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “__MONTH=07”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [s@sub-record-check:6] Set(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “__YEAR=2020”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [s@sub-record-check:7] Set(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “__TIMESTR=20200709-093339”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [s@sub-record-check:8] Set(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “__FROMEXTEN=unknown”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [s@sub-record-check:9] Set(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “__MON_FMT=wav”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [s@sub-record-check:10] NoOp(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “Recordings initialized”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [s@sub-record-check:11] ExecIf(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “0?Set(ARG3=dontcare)”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [s@sub-record-check:12] Set(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “REC_POLICY_MODE_SAVE=”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [s@sub-record-check:13] ExecIf(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “0?Set(REC_STATUS=NO)”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [s@sub-record-check:14] GotoIf(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “2?checkaction”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx_builtins.c: Goto (sub-record-check,s,17)
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [s@sub-record-check:17] GotoIf(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “1?sub-record-check,in,1”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx_builtins.c: Goto (sub-record-check,in,1)
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [in@sub-record-check:1] NoOp(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “Inbound Recording Check to 7022976605”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [in@sub-record-check:2] Set(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “FROMEXTEN=unknown”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [in@sub-record-check:3] ExecIf(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “10?Set(FROMEXTEN=7028405011)”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [in@sub-record-check:4] Gosub(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “recordcheck,1(dontcare,in,7022976605)”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “Starting recording check against dontcare”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [recordcheck@sub-record-check:2] Goto(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “dontcare”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [recordcheck@sub-record-check:3] Return(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [in@sub-record-check:5] Return(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [7022976605@from-pstn:3] Set(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “__FROM_DID=7022976605”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [7022976605@from-pstn:4] Set(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “returnhere=1”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [7022976605@from-pstn:5] Gosub(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “app-blacklist-check,s,1()”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [s@app-blacklist-check:1] GotoIf(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “0?blacklisted”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [s@app-blacklist-check:2] Set(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “CALLED_BLACKLIST=1”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [s@app-blacklist-check:3] Return(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [7022976605@from-pstn:6] Set(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “CDR(did)=7022976605”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [7022976605@from-pstn:7] GotoIf(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “0?”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [7022976605@from-pstn:8] ExecIf(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “1 ?Set(CALLERID(name)=7028405011)”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [7022976605@from-pstn:9] Set(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “__MOHCLASS=”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [7022976605@from-pstn:10] Set(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “__REVERSAL_REJECT=FALSE”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [7022976605@from-pstn:11] GotoIf(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “1?post-reverse-charge”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx_builtins.c: Goto (from-pstn,7022976605,13)
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [7022976605@from-pstn:13] NoOp(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [7022976605@from-pstn:14] Set(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “__CALLINGNAMEPRES_SV=allowed_not_screened”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [7022976605@from-pstn:15] Set(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “__CALLINGNUMPRES_SV=allowed_not_screened”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [7022976605@from-pstn:16] Set(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “CALLERID(name-pres)=allowed_not_screened”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [7022976605@from-pstn:17] Set(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “CALLERID(num-pres)=allowed_not_screened”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [7022976605@from-pstn:18] NoOp(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “CallerID Entry Point”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [7022976605@from-pstn:19] Set(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “__CRM_DIRECTION=INBOUND”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [7022976605@from-pstn:20] Set(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “__CRM_SOURCE=7028405011”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [7022976605@from-pstn:21] Set(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “__CRM_LINKEDID=1594312419.49”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [7022976605@from-pstn:22] ExecIf(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “1?Set(CHANNEL(hangup_handler_push)=crm-hangup,s,1)”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [7022976605@from-pstn:23] Goto(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “ivr-1,s,1”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx_builtins.c: Goto (ivr-1,s,1)
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [s@ivr-1:1] Set(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “TIMEOUT_LOOPCOUNT=0”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [s@ivr-1:2] Set(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “INVALID_LOOPCOUNT=0”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [s@ivr-1:3] Set(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “_IVR_CONTEXT_ivr-1=”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [s@ivr-1:4] Set(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “_IVR_CONTEXT=ivr-1”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [s@ivr-1:5] Set(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “__IVR_RETVM=”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [s@ivr-1:6] GotoIf(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “0?skip”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [s@ivr-1:7] Answer(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “”) in new stack
[2020-07-09 09:33:39] VERBOSE[16479][C-00000025] pbx.c: Executing [s@ivr-1:8] Wait(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “1”) in new stack
[2020-07-09 09:33:40] VERBOSE[16479][C-00000025] pbx.c: Executing [s@ivr-1:9] Set(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “IVR_MSG=custom/main_ivr_greeting”) in new stack
[2020-07-09 09:33:40] VERBOSE[16479][C-00000025] pbx.c: Executing [s@ivr-1:10] Set(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “TIMEOUT(digit)=3”) in new stack
[2020-07-09 09:33:40] VERBOSE[16479][C-00000025] func_timeout.c: Digit timeout set to 3.000
[2020-07-09 09:33:40] VERBOSE[16479][C-00000025] pbx.c: Executing [s@ivr-1:11] ExecIf(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “1?Background(custom/main_ivr_greeting)”) in new stack
[2020-07-09 09:33:40] VERBOSE[16479][C-00000025] file.c: <PJSIP/Twilio-US1-North-America-Virgina-00000031> Playing ‘custom/main_ivr_greeting.ulaw’ (language ‘en’)
[2020-07-09 09:33:58] VERBOSE[16479][C-00000025] pbx.c: Executing [s@ivr-1:12] WaitExten(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “10,”) in new stack
[2020-07-09 09:34:08] VERBOSE[16479][C-00000025] pbx_builtins.c: Timeout on PJSIP/Twilio-US1-North-America-Virgina-00000031, going to ‘t’
[2020-07-09 09:34:08] VERBOSE[16479][C-00000025] pbx.c: Executing [t@ivr-1:1] Set(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “TIMEOUT_LOOPCOUNT=1”) in new stack
[2020-07-09 09:34:08] VERBOSE[16479][C-00000025] pbx.c: Executing [t@ivr-1:2] GotoIf(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “0?final”) in new stack
[2020-07-09 09:34:08] VERBOSE[16479][C-00000025] pbx.c: Executing [t@ivr-1:3] Set(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “IVR_MSG=no-valid-responce-pls-try-again”) in new stack
[2020-07-09 09:34:08] VERBOSE[16479][C-00000025] pbx.c: Executing [t@ivr-1:4] Goto(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “s,start”) in new stack
[2020-07-09 09:34:08] VERBOSE[16479][C-00000025] pbx_builtins.c: Goto (ivr-1,s,10)
[2020-07-09 09:34:08] VERBOSE[16479][C-00000025] pbx.c: Executing [s@ivr-1:10] Set(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “TIMEOUT(digit)=3”) in new stack
[2020-07-09 09:34:08] VERBOSE[16479][C-00000025] func_timeout.c: Digit timeout set to 3.000
[2020-07-09 09:34:08] VERBOSE[16479][C-00000025] pbx.c: Executing [s@ivr-1:11] ExecIf(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “1?Background(no-valid-responce-pls-try-again)”) in new stack
[2020-07-09 09:34:08] VERBOSE[16479][C-00000025] file.c: <PJSIP/Twilio-US1-North-America-Virgina-00000031> Playing ‘no-valid-responce-pls-try-again.slin’ (language ‘en’)
[2020-07-09 09:34:11] VERBOSE[16479][C-00000025] pbx.c: Spawn extension (ivr-1, s, 11) exited non-zero on ‘PJSIP/Twilio-US1-North-America-Virgina-00000031’
[2020-07-09 09:34:11] VERBOSE[16479][C-00000025] pbx.c: Executing [h@ivr-1:1] Hangup(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “”) in new stack
[2020-07-09 09:34:11] VERBOSE[16479][C-00000025] pbx.c: Spawn extension (ivr-1, h, 1) exited non-zero on ‘PJSIP/Twilio-US1-North-America-Virgina-00000031’
[2020-07-09 09:34:11] VERBOSE[16479][C-00000025] app_stack.c: PJSIP/Twilio-US1-North-America-Virgina-00000031 Internal Gosub(crm-hangup,s,1) start
[2020-07-09 09:34:11] VERBOSE[16479][C-00000025] pbx.c: Executing [s@crm-hangup:1] NoOp(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “Sending Hangup to CRM”) in new stack
[2020-07-09 09:34:11] VERBOSE[16479][C-00000025] pbx.c: Executing [s@crm-hangup:2] NoOp(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “HANGUP CAUSE: 18”) in new stack
[2020-07-09 09:34:11] VERBOSE[16479][C-00000025] pbx.c: Executing [s@crm-hangup:3] ExecIf(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “0?Set(__CRM_VOICEMAIL=)”) in new stack
[2020-07-09 09:34:11] VERBOSE[16479][C-00000025] pbx.c: Executing [s@crm-hangup:4] NoOp(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “MASTER CHANNEL: 1594312419.49 = 1594312419.49”) in new stack
[2020-07-09 09:34:11] VERBOSE[16479][C-00000025] pbx.c: Executing [s@crm-hangup:5] GotoIf(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “0?return”) in new stack
[2020-07-09 09:34:11] VERBOSE[16479][C-00000025] pbx.c: Executing [s@crm-hangup:6] Set(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “__CRM_HANGUP=1”) in new stack
[2020-07-09 09:34:11] VERBOSE[16479][C-00000025] pbx.c: Executing [s@crm-hangup:7] AGI(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “sangomacrm.agi”) in new stack
[2020-07-09 09:34:11] VERBOSE[16479][C-00000025] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/sangomacrm.agi
[2020-07-09 09:34:11] VERBOSE[16479][C-00000025] res_agi.c: <PJSIP/Twilio-US1-North-America-Virgina-00000031>AGI Script sangomacrm.agi completed, returning 0
[2020-07-09 09:34:11] VERBOSE[16479][C-00000025] pbx.c: Executing [s@crm-hangup:8] Return(“PJSIP/Twilio-US1-North-America-Virgina-00000031”, “”) in new stack
[2020-07-09 09:34:11] VERBOSE[16479][C-00000025] app_stack.c: Spawn extension (ivr-1, h, 1) exited non-zero on ‘PJSIP/Twilio-US1-North-America-Virgina-00000031’
[2020-07-09 09:34:11] VERBOSE[16479][C-00000025] app_stack.c: PJSIP/Twilio-US1-North-America-Virgina-00000031 Internal Gosub(crm-hangup,s,1) complete GOSUB_RETVAL=

intrigue · July 9, 2020, 5:11pm

First step would be to verify your NAT settings under Settings-Asterisk-SIP
You’ll want to make sure that the proper external IP is configured for “External Address” uner General SIP Settings, and there are a few options under Chan SIP tab as well

Next verify your local subnet(s) of the phones are configured within local networks.

You’ll also want to verify that your Meraki is allowing RTP and SIP traffic through the firewall.

rnrstar · July 9, 2020, 6:07pm

Yes, I should have pointed that out. The external address is set correctly and I have the local network defined as well. I’m using pjsip for my twilio trunks as well as for the extensions. I’m thinking my next step is to revert to chan_sip for the trunks.

As far as I can tell, the Meraki is allow SIP and RTP as it’s showing that as part of the traffic coming from that IP and I’m not seeing anything that would indicate it’s being blocked.

rnrstar · July 9, 2020, 6:41pm

I tried to use chan_sip for the twilio trunks and same issue.

system · August 9, 2020, 6:41pm

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