Freepbx ivr trim user input number

tesspbx · October 7, 2022, 11:48am

Hi all. FreePBX 16.0.21.18 (Asterisk 13.38.3) (also earlier versions, the update did not solve the problem), when calling to the IVR, cuts off the number entered by the user, and cuts it randomly. User enters 1234 both during the playback of the announcement and after, in logs:

app_read.c: User entered ‘23’
app_read.c: User entered ‘12’
app_read.c: User entered ‘1’
app_read.c: User entered ‘34’
app_read.c: User entered nothing. etc.

In very rare cases, the system accepts the full number and the call goes through, but this happens once in a hundred.

In extension_additional.conf all Playback was replaced by background, it didn’t help.
Force Strict Dial Timeout turned on and off, tried the timeout from 0 to 10 seconds - does not help.
I don’t know where else to look, plshlp

david55 · October 7, 2022, 1:31pm

Background isn’t intended to be used in combination with Read. (Are you doing something unusual, like executing these from AGI?)

You need to enable DTMF debugging and provide the output.

You also need to specify what protocol you using, and, if a VoIP one, whether DTMF is inband, RFC 4733, or INFO.

Asterisk 13 is almost a year beyond end of life.

tesspbx · October 8, 2022, 5:22am

Operator provides SIP-trunk with DTMF mode RFC2833

Next log

I call the server from my mobile phone and try to dial 2014 (extension on another server, custom destionation are registered and working) and 5399 (extension on this server). IVR points - 6, 7, 8, 0

dtmf log

[2022-10-08 12:05:58] VERBOSE[2711] chan_sip.c: Reloading SIP
[2022-10-08 12:05:58] VERBOSE[2711] netsock2.c: Using SIP TOS bits 96
[2022-10-08 12:05:58] VERBOSE[2711] netsock2.c: Using SIP CoS mark 4
[2022-10-08 12:07:12] VERBOSE[2711][C-00000bbc] netsock2.c: Using SIP RTP TOS bits 184
[2022-10-08 12:07:12] VERBOSE[2711][C-00000bbc] netsock2.c: Using SIP RTP CoS mark 5
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [883140776398475@from-trunk-sip-mtt_ip_out:1] Set(“SIP/mtt_ip_in-00000008”, “GROUP()=OUT_1”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [883140776398475@from-trunk-sip-mtt_ip_out:2] Goto(“SIP/mtt_ip_in-00000008”, “from-trunk,883140776398475,1”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx_builtins.c: Goto (from-trunk,883140776398475,1)
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [883140776398475@from-trunk:1] NoOp(“SIP/mtt_ip_in-00000008”, “Catch-All DID Match - Found 883140776398475 - You probably want a DID for this.”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [883140776398475@from-trunk:2] Set(“SIP/mtt_ip_in-00000008”, “__FROM_DID=883140776398475”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [883140776398475@from-trunk:3] Goto(“SIP/mtt_ip_in-00000008”, “ext-did,s,1”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx_builtins.c: Goto (ext-did,s,1)
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ext-did:1] Set(“SIP/mtt_ip_in-00000008”, “__DIRECTION=INBOUND”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ext-did:2] Set(“SIP/mtt_ip_in-00000008”, “CHANNEL(language)=ru”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ext-did:3] Gosub(“SIP/mtt_ip_in-00000008”, “sub-record-check,s,1(in,s,force)”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@sub-record-check:1] GotoIf(“SIP/mtt_ip_in-00000008”, “0?initialized”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@sub-record-check:2] Set(“SIP/mtt_ip_in-00000008”, “__REC_STATUS=INITIALIZED”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@sub-record-check:3] Set(“SIP/mtt_ip_in-00000008”, “NOW=1665205632”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@sub-record-check:4] Set(“SIP/mtt_ip_in-00000008”, “__DAY=08”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@sub-record-check:5] Set(“SIP/mtt_ip_in-00000008”, “__MONTH=10”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@sub-record-check:6] Set(“SIP/mtt_ip_in-00000008”, “__YEAR=2022”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@sub-record-check:7] Set(“SIP/mtt_ip_in-00000008”, “__TIMESTR=20221008-120712”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@sub-record-check:8] Set(“SIP/mtt_ip_in-00000008”, “__FROMEXTEN=unknown”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@sub-record-check:9] Set(“SIP/mtt_ip_in-00000008”, “__MON_FMT=wav”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@sub-record-check:10] NoOp(“SIP/mtt_ip_in-00000008”, “Recordings initialized”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@sub-record-check:11] ExecIf(“SIP/mtt_ip_in-00000008”, “0?Set(ARG3=dontcare)”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@sub-record-check:12] Set(“SIP/mtt_ip_in-00000008”, “REC_POLICY_MODE_SAVE=”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@sub-record-check:13] ExecIf(“SIP/mtt_ip_in-00000008”, “0?Set(REC_STATUS=NO)”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@sub-record-check:14] GotoIf(“SIP/mtt_ip_in-00000008”, “2?checkaction”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx_builtins.c: Goto (sub-record-check,s,17)
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@sub-record-check:17] GotoIf(“SIP/mtt_ip_in-00000008”, “1?sub-record-check,in,1”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx_builtins.c: Goto (sub-record-check,in,1)
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [in@sub-record-check:1] NoOp(“SIP/mtt_ip_in-00000008”, “Inbound Recording Check to s”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [in@sub-record-check:2] Set(“SIP/mtt_ip_in-00000008”, “FROMEXTEN=unknown”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [in@sub-record-check:3] ExecIf(“SIP/mtt_ip_in-00000008”, “11?Set(FROMEXTEN=79825199215)”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [in@sub-record-check:4] Gosub(“SIP/mtt_ip_in-00000008”, “recordcheck,1(force,in,s)”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp(“SIP/mtt_ip_in-00000008”, “Starting recording check against force”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [recordcheck@sub-record-check:2] Goto(“SIP/mtt_ip_in-00000008”, “force”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx_builtins.c: Goto (sub-record-check,recordcheck,5)
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [recordcheck@sub-record-check:5] Set(“SIP/mtt_ip_in-00000008”, “__REC_POLICY_MODE=FORCE”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [recordcheck@sub-record-check:6] GotoIf(“SIP/mtt_ip_in-00000008”, “1?startrec”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx_builtins.c: Goto (sub-record-check,recordcheck,16)
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [recordcheck@sub-record-check:16] NoOp(“SIP/mtt_ip_in-00000008”, “Starting recording: in, s”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [recordcheck@sub-record-check:17] Set(“SIP/mtt_ip_in-00000008”, “__CALLFILENAME=in-s-79825199215-20221008-120712-1665205632.15”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [recordcheck@sub-record-check:18] MixMonitor(“SIP/mtt_ip_in-00000008”, “2022/10/08/in-s-79825199215-20221008-120712-1665205632.15.wav,abi(),”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [recordcheck@sub-record-check:19] Set(“SIP/mtt_ip_in-00000008”, “__MIXMON_ID=”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [recordcheck@sub-record-check:20] Set(“SIP/mtt_ip_in-00000008”, “__RECORD_ID=SIP/mtt_ip_in-00000008”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [recordcheck@sub-record-check:21] Set(“SIP/mtt_ip_in-00000008”, “__REC_STATUS=RECORDING”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [recordcheck@sub-record-check:22] Set(“SIP/mtt_ip_in-00000008”, “CDR(recordingfile)=in-s-79825199215-20221008-120712-1665205632.15.wav”) in new stack
[2022-10-08 12:07:12] VERBOSE[79654][C-00000bbc] app_mixmonitor.c: Begin MixMonitor Recording SIP/mtt_ip_in-00000008
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [recordcheck@sub-record-check:23] Return(“SIP/mtt_ip_in-00000008”, “”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [in@sub-record-check:5] Return(“SIP/mtt_ip_in-00000008”, “”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ext-did:4] Set(“SIP/mtt_ip_in-00000008”, “CHANNEL(tonezone)=ru”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ext-did:5] ExecIf(“SIP/mtt_ip_in-00000008”, “0?Set(__FROM_DID=s)”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ext-did:6] Set(“SIP/mtt_ip_in-00000008”, “returnhere=1”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ext-did:7] Gosub(“SIP/mtt_ip_in-00000008”, “app-blacklist-check,s,1()”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@app-blacklist-check:1] GotoIf(“SIP/mtt_ip_in-00000008”, “0?blacklisted”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@app-blacklist-check:2] Set(“SIP/mtt_ip_in-00000008”, “CALLED_BLACKLIST=1”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@app-blacklist-check:3] Return(“SIP/mtt_ip_in-00000008”, “”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ext-did:8] Set(“SIP/mtt_ip_in-00000008”, “CDR(did)=883140776398475”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ext-did:9] GotoIf(“SIP/mtt_ip_in-00000008”, “0?”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ext-did:10] ExecIf(“SIP/mtt_ip_in-00000008”, “0 ?Set(CALLERID(name)=79825199215)”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ext-did:11] Set(“SIP/mtt_ip_in-00000008”, “__MOHCLASS=”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ext-did:12] Set(“SIP/mtt_ip_in-00000008”, “__REVERSAL_REJECT=FALSE”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ext-did:13] GotoIf(“SIP/mtt_ip_in-00000008”, “1?post-reverse-charge”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx_builtins.c: Goto (ext-did,s,15)
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ext-did:15] NoOp(“SIP/mtt_ip_in-00000008”, “”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ext-did:16] Set(“SIP/mtt_ip_in-00000008”, “__CALLINGNAMEPRES_SV=allowed_not_screened”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ext-did:17] Set(“SIP/mtt_ip_in-00000008”, “__CALLINGNUMPRES_SV=allowed_not_screened”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ext-did:18] Set(“SIP/mtt_ip_in-00000008”, “CALLERID(name-pres)=allowed_not_screened”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ext-did:19] Set(“SIP/mtt_ip_in-00000008”, “CALLERID(num-pres)=allowed_not_screened”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ext-did:20] NoOp(“SIP/mtt_ip_in-00000008”, “CallerID Entry Point”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ext-did:21] Set(“SIP/mtt_ip_in-00000008”, “__CRM_DIRECTION=INBOUND”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ext-did:22] Set(“SIP/mtt_ip_in-00000008”, “__CRM_SOURCE=79825199215”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ext-did:23] Set(“SIP/mtt_ip_in-00000008”, “__CRM_LINKEDID=1665205632.15”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ext-did:24] AGI(“SIP/mtt_ip_in-00000008”, “agi://127.0.0.1/sangomacrm.agi,true”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] res_agi.c: <SIP/mtt_ip_in-00000008>AGI Script agi://127.0.0.1/sangomacrm.agi completed, returning 0
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ext-did:25] ExecIf(“SIP/mtt_ip_in-00000008”, “1?Set(CHANNEL(hangup_handler_push)=crm-hangup,s,1)”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ext-did:26] Goto(“SIP/mtt_ip_in-00000008”, “ivr-7,s,1”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx_builtins.c: Goto (ivr-7,s,1)
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ivr-7:1] Set(“SIP/mtt_ip_in-00000008”, “TIMEOUT_LOOPCOUNT=0”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ivr-7:2] Set(“SIP/mtt_ip_in-00000008”, “INVALID_LOOPCOUNT=0”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ivr-7:3] Set(“SIP/mtt_ip_in-00000008”, “_IVR_CONTEXT_ivr-7=”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ivr-7:4] Set(“SIP/mtt_ip_in-00000008”, “_IVR_CONTEXT=ivr-7”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ivr-7:5] Set(“SIP/mtt_ip_in-00000008”, “__IVR_RETVM=”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ivr-7:6] GotoIf(“SIP/mtt_ip_in-00000008”, “0?skip”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ivr-7:7] Answer(“SIP/mtt_ip_in-00000008”, “”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ivr-7:8] Set(“SIP/mtt_ip_in-00000008”, “IVR_MSG=custom/IVR_level1&custom/IVR_level1”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ivr-7:9] Set(“SIP/mtt_ip_in-00000008”, “TIMEOUT(digit)=5”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] func_timeout.c: Digit timeout set to 5.000
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ivr-7:10] Read(“SIP/mtt_ip_in-00000008”, “IVREXT,custom/IVR_level1&custom/IVR_level1,0,5”) in new stack
[2022-10-08 12:07:12] VERBOSE[79653][C-00000bbc] file.c: <SIP/mtt_ip_in-00000008> Playing ‘custom/IVR_level1.ulaw’ (language ‘ru’)
[2022-10-08 12:07:40] VERBOSE[79653][C-00000bbc] file.c: <SIP/mtt_ip_in-00000008> Playing ‘custom/IVR_level1.ulaw’ (language ‘ru’)
[2022-10-08 12:07:56] DTMF[79653][C-00000bbc] channel.c: DTMF begin ‘4’ received on SIP/mtt_ip_in-00000008
[2022-10-08 12:07:56] DTMF[79653][C-00000bbc] channel.c: DTMF begin ignored ‘4’ on SIP/mtt_ip_in-00000008
[2022-10-08 12:07:56] DTMF[79653][C-00000bbc] channel.c: DTMF end ‘4’ received on SIP/mtt_ip_in-00000008, duration 35 ms
[2022-10-08 12:07:56] DTMF[79653][C-00000bbc] channel.c: DTMF end passthrough ‘4’ on SIP/mtt_ip_in-00000008
[2022-10-08 12:07:57] DTMF[79653][C-00000bbc] channel.c: DTMF begin ‘0’ received on SIP/mtt_ip_in-00000008
[2022-10-08 12:07:57] DTMF[79653][C-00000bbc] channel.c: DTMF begin ignored ‘0’ on SIP/mtt_ip_in-00000008
[2022-10-08 12:07:57] DTMF[79653][C-00000bbc] channel.c: DTMF end ‘0’ received on SIP/mtt_ip_in-00000008, duration 35 ms
[2022-10-08 12:07:57] DTMF[79653][C-00000bbc] channel.c: DTMF end passthrough ‘0’ on SIP/mtt_ip_in-00000008
[2022-10-08 12:08:02] VERBOSE[79653][C-00000bbc] app_read.c: User entered ‘40’
[2022-10-08 12:08:02] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ivr-7:11] GotoIf(“SIP/mtt_ip_in-00000008”, “0?#,1”) in new stack
[2022-10-08 12:08:02] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ivr-7:12] GotoIf(“SIP/mtt_ip_in-00000008”, “0?t,1”) in new stack
[2022-10-08 12:08:02] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ivr-7:13] ExecIf(“SIP/mtt_ip_in-00000008”, “0?Set(LOCALEXT=1)”) in new stack
[2022-10-08 12:08:02] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ivr-7:14] GotoIf(“SIP/mtt_ip_in-00000008”, “0?i,1”) in new stack
[2022-10-08 12:08:02] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ivr-7:15] GotoIf(“SIP/mtt_ip_in-00000008”, “0?from-did-direct-ivr,40,1”) in new stack
[2022-10-08 12:08:02] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ivr-7:16] Goto(“SIP/mtt_ip_in-00000008”, “40,1”) in new stack
[2022-10-08 12:08:02] VERBOSE[79653][C-00000bbc] pbx_builtins.c: Goto (ivr-7,40,1)
[2022-10-08 12:08:02] VERBOSE[79653][C-00000bbc] pbx.c: Channel ‘SIP/mtt_ip_in-00000008’ sent to invalid extension: context,exten,priority=ivr-7,40,1
[2022-10-08 12:08:02] VERBOSE[79653][C-00000bbc] pbx.c: Executing [i@ivr-7:1] Set(“SIP/mtt_ip_in-00000008”, “INVALID_LOOPCOUNT=1”) in new stack
[2022-10-08 12:08:02] VERBOSE[79653][C-00000bbc] pbx.c: Executing [i@ivr-7:2] GotoIf(“SIP/mtt_ip_in-00000008”, “0?final”) in new stack
[2022-10-08 12:08:02] VERBOSE[79653][C-00000bbc] pbx.c: Executing [i@ivr-7:3] Set(“SIP/mtt_ip_in-00000008”, “IVR_MSG=no-valid-responce-pls-try-again”) in new stack
[2022-10-08 12:08:02] VERBOSE[79653][C-00000bbc] pbx.c: Executing [i@ivr-7:4] Goto(“SIP/mtt_ip_in-00000008”, “s,start”) in new stack
[2022-10-08 12:08:02] VERBOSE[79653][C-00000bbc] pbx_builtins.c: Goto (ivr-7,s,9)
[2022-10-08 12:08:02] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ivr-7:9] Set(“SIP/mtt_ip_in-00000008”, “TIMEOUT(digit)=5”) in new stack
[2022-10-08 12:08:02] VERBOSE[79653][C-00000bbc] func_timeout.c: Digit timeout set to 5.000
[2022-10-08 12:08:02] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ivr-7:10] Read(“SIP/mtt_ip_in-00000008”, “IVREXT,no-valid-responce-pls-try-again,0,5”) in new stack
[2022-10-08 12:08:02] VERBOSE[79653][C-00000bbc] file.c: <SIP/mtt_ip_in-00000008> Playing ‘no-valid-responce-pls-try-again.ulaw’ (language ‘ru’)
[2022-10-08 12:08:11] VERBOSE[79653][C-00000bbc] app_read.c: User entered nothing.
[2022-10-08 12:08:11] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ivr-7:11] GotoIf(“SIP/mtt_ip_in-00000008”, “0?#,1”) in new stack
[2022-10-08 12:08:11] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ivr-7:12] GotoIf(“SIP/mtt_ip_in-00000008”, “1?t,1”) in new stack
[2022-10-08 12:08:11] VERBOSE[79653][C-00000bbc] pbx_builtins.c: Goto (ivr-7,t,1)
[2022-10-08 12:08:11] VERBOSE[79653][C-00000bbc] pbx.c: Executing [t@ivr-7:1] Set(“SIP/mtt_ip_in-00000008”, “TIMEOUT_LOOPCOUNT=1”) in new stack
[2022-10-08 12:08:11] VERBOSE[79653][C-00000bbc] pbx.c: Executing [t@ivr-7:2] GotoIf(“SIP/mtt_ip_in-00000008”, “0?final”) in new stack
[2022-10-08 12:08:11] VERBOSE[79653][C-00000bbc] pbx.c: Executing [t@ivr-7:3] Set(“SIP/mtt_ip_in-00000008”, “IVR_MSG=no-valid-responce-pls-try-again”) in new stack
[2022-10-08 12:08:11] VERBOSE[79653][C-00000bbc] pbx.c: Executing [t@ivr-7:4] Goto(“SIP/mtt_ip_in-00000008”, “s,start”) in new stack
[2022-10-08 12:08:11] VERBOSE[79653][C-00000bbc] pbx_builtins.c: Goto (ivr-7,s,9)
[2022-10-08 12:08:11] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ivr-7:9] Set(“SIP/mtt_ip_in-00000008”, “TIMEOUT(digit)=5”) in new stack
[2022-10-08 12:08:11] VERBOSE[79653][C-00000bbc] func_timeout.c: Digit timeout set to 5.000
[2022-10-08 12:08:11] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ivr-7:10] Read(“SIP/mtt_ip_in-00000008”, “IVREXT,no-valid-responce-pls-try-again,0,5”) in new stack
[2022-10-08 12:08:11] VERBOSE[79653][C-00000bbc] file.c: <SIP/mtt_ip_in-00000008> Playing ‘no-valid-responce-pls-try-again.ulaw’ (language ‘ru’)
[2022-10-08 12:08:21] VERBOSE[79653][C-00000bbc] app_read.c: User entered nothing.
[2022-10-08 12:08:21] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ivr-7:11] GotoIf(“SIP/mtt_ip_in-00000008”, “0?#,1”) in new stack
[2022-10-08 12:08:21] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ivr-7:12] GotoIf(“SIP/mtt_ip_in-00000008”, “1?t,1”) in new stack
[2022-10-08 12:08:21] VERBOSE[79653][C-00000bbc] pbx_builtins.c: Goto (ivr-7,t,1)
[2022-10-08 12:08:21] VERBOSE[79653][C-00000bbc] pbx.c: Executing [t@ivr-7:1] Set(“SIP/mtt_ip_in-00000008”, “TIMEOUT_LOOPCOUNT=2”) in new stack
[2022-10-08 12:08:21] VERBOSE[79653][C-00000bbc] pbx.c: Executing [t@ivr-7:2] GotoIf(“SIP/mtt_ip_in-00000008”, “0?final”) in new stack
[2022-10-08 12:08:21] VERBOSE[79653][C-00000bbc] pbx.c: Executing [t@ivr-7:3] Set(“SIP/mtt_ip_in-00000008”, “IVR_MSG=no-valid-responce-pls-try-again”) in new stack
[2022-10-08 12:08:21] VERBOSE[79653][C-00000bbc] pbx.c: Executing [t@ivr-7:4] Goto(“SIP/mtt_ip_in-00000008”, “s,start”) in new stack
[2022-10-08 12:08:21] VERBOSE[79653][C-00000bbc] pbx_builtins.c: Goto (ivr-7,s,9)
[2022-10-08 12:08:21] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ivr-7:9] Set(“SIP/mtt_ip_in-00000008”, “TIMEOUT(digit)=5”) in new stack
[2022-10-08 12:08:21] VERBOSE[79653][C-00000bbc] func_timeout.c: Digit timeout set to 5.000
[2022-10-08 12:08:21] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ivr-7:10] Read(“SIP/mtt_ip_in-00000008”, “IVREXT,no-valid-responce-pls-try-again,0,5”) in new stack
[2022-10-08 12:08:21] VERBOSE[79653][C-00000bbc] file.c: <SIP/mtt_ip_in-00000008> Playing ‘no-valid-responce-pls-try-again.ulaw’ (language ‘ru’)
[2022-10-08 12:08:30] VERBOSE[79653][C-00000bbc] app_read.c: User entered nothing.
[2022-10-08 12:08:30] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ivr-7:11] GotoIf(“SIP/mtt_ip_in-00000008”, “0?#,1”) in new stack
[2022-10-08 12:08:30] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ivr-7:12] GotoIf(“SIP/mtt_ip_in-00000008”, “1?t,1”) in new stack
[2022-10-08 12:08:30] VERBOSE[79653][C-00000bbc] pbx_builtins.c: Goto (ivr-7,t,1)
[2022-10-08 12:08:30] VERBOSE[79653][C-00000bbc] pbx.c: Executing [t@ivr-7:1] Set(“SIP/mtt_ip_in-00000008”, “TIMEOUT_LOOPCOUNT=3”) in new stack
[2022-10-08 12:08:30] VERBOSE[79653][C-00000bbc] pbx.c: Executing [t@ivr-7:2] GotoIf(“SIP/mtt_ip_in-00000008”, “0?final”) in new stack
[2022-10-08 12:08:30] VERBOSE[79653][C-00000bbc] pbx.c: Executing [t@ivr-7:3] Set(“SIP/mtt_ip_in-00000008”, “IVR_MSG=no-valid-responce-pls-try-again”) in new stack
[2022-10-08 12:08:30] VERBOSE[79653][C-00000bbc] pbx.c: Executing [t@ivr-7:4] Goto(“SIP/mtt_ip_in-00000008”, “s,start”) in new stack
[2022-10-08 12:08:30] VERBOSE[79653][C-00000bbc] pbx_builtins.c: Goto (ivr-7,s,9)
[2022-10-08 12:08:30] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ivr-7:9] Set(“SIP/mtt_ip_in-00000008”, “TIMEOUT(digit)=5”) in new stack
[2022-10-08 12:08:30] VERBOSE[79653][C-00000bbc] func_timeout.c: Digit timeout set to 5.000
[2022-10-08 12:08:30] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ivr-7:10] Read(“SIP/mtt_ip_in-00000008”, “IVREXT,no-valid-responce-pls-try-again,0,5”) in new stack
[2022-10-08 12:08:30] VERBOSE[79653][C-00000bbc] file.c: <SIP/mtt_ip_in-00000008> Playing ‘no-valid-responce-pls-try-again.ulaw’ (language ‘ru’)
[2022-10-08 12:08:39] VERBOSE[79653][C-00000bbc] app_read.c: User entered nothing.
[2022-10-08 12:08:39] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ivr-7:11] GotoIf(“SIP/mtt_ip_in-00000008”, “0?#,1”) in new stack
[2022-10-08 12:08:39] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@ivr-7:12] GotoIf(“SIP/mtt_ip_in-00000008”, “1?t,1”) in new stack
[2022-10-08 12:08:39] VERBOSE[79653][C-00000bbc] pbx_builtins.c: Goto (ivr-7,t,1)
[2022-10-08 12:08:39] VERBOSE[79653][C-00000bbc] pbx.c: Executing [t@ivr-7:1] Set(“SIP/mtt_ip_in-00000008”, “TIMEOUT_LOOPCOUNT=4”) in new stack
[2022-10-08 12:08:39] VERBOSE[79653][C-00000bbc] pbx.c: Executing [t@ivr-7:2] GotoIf(“SIP/mtt_ip_in-00000008”, “1?final”) in new stack
[2022-10-08 12:08:39] VERBOSE[79653][C-00000bbc] pbx_builtins.c: Goto (ivr-7,t,5)
[2022-10-08 12:08:39] VERBOSE[79653][C-00000bbc] pbx.c: Executing [t@ivr-7:5] Playback(“SIP/mtt_ip_in-00000008”, “no-valid-responce-transfering”) in new stack
[2022-10-08 12:08:39] VERBOSE[79653][C-00000bbc] file.c: <SIP/mtt_ip_in-00000008> Playing ‘no-valid-responce-transfering.ulaw’ (language ‘ru’)
[2022-10-08 12:08:41] VERBOSE[79653][C-00000bbc] pbx.c: Executing [h@ivr-7:1] Hangup(“SIP/mtt_ip_in-00000008”, “”) in new stack
[2022-10-08 12:08:41] VERBOSE[79653][C-00000bbc] pbx.c: Spawn extension (ivr-7, h, 1) exited non-zero on ‘SIP/mtt_ip_in-00000008’
[2022-10-08 12:08:41] VERBOSE[79653][C-00000bbc] app_stack.c: SIP/mtt_ip_in-00000008 Internal Gosub(crm-hangup,s,1) start
[2022-10-08 12:08:41] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@crm-hangup:1] NoOp(“SIP/mtt_ip_in-00000008”, “Sending Hangup to CRM”) in new stack
[2022-10-08 12:08:41] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@crm-hangup:2] NoOp(“SIP/mtt_ip_in-00000008”, “HANGUP CAUSE: 16”) in new stack
[2022-10-08 12:08:41] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@crm-hangup:3] ExecIf(“SIP/mtt_ip_in-00000008”, “0?Set(__CRM_VOICEMAIL=)”) in new stack
[2022-10-08 12:08:41] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@crm-hangup:4] NoOp(“SIP/mtt_ip_in-00000008”, “MASTER CHANNEL: 1665205632.15 = 1665205632.15”) in new stack
[2022-10-08 12:08:41] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@crm-hangup:5] GotoIf(“SIP/mtt_ip_in-00000008”, “0?return”) in new stack
[2022-10-08 12:08:41] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@crm-hangup:6] Set(“SIP/mtt_ip_in-00000008”, “__CRM_HANGUP=1”) in new stack
[2022-10-08 12:08:41] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@crm-hangup:7] AGI(“SIP/mtt_ip_in-00000008”, “agi://127.0.0.1/sangomacrm.agi”) in new stack
[2022-10-08 12:08:41] VERBOSE[79653][C-00000bbc] res_agi.c: <SIP/mtt_ip_in-00000008>AGI Script agi://127.0.0.1/sangomacrm.agi completed, returning 0
[2022-10-08 12:08:41] VERBOSE[79653][C-00000bbc] pbx.c: Executing [s@crm-hangup:8] Return(“SIP/mtt_ip_in-00000008”, “”) in new stack
[2022-10-08 12:08:41] VERBOSE[79653][C-00000bbc] app_stack.c: Spawn extension (ivr-7, h, 1) exited non-zero on ‘SIP/mtt_ip_in-00000008’
[2022-10-08 12:08:41] VERBOSE[79653][C-00000bbc] app_stack.c: SIP/mtt_ip_in-00000008 Internal Gosub(crm-hangup,s,1) complete GOSUB_RETVAL=
[2022-10-08 12:08:41] VERBOSE[79654][C-00000bbc] app_mixmonitor.c: MixMonitor close filestream (mixed)
[2022-10-08 12:08:41] VERBOSE[79654][C-00000bbc] app_mixmonitor.c: End MixMonitor Recording SIP/mtt_ip_in-00000008

tesspbx · October 8, 2022, 8:41am

I forgot to say, I tried to deploy a new server on FreePBX 16 in Asterisk 18, the problem did not go away

david55 · October 8, 2022, 9:21am

You only received 40 from the provider in that log. For further confirmation you would need to enable RTP debugging, or capture the RTP upstream of Asteirsk (tcpdump + wireshark, or possibly sngrep).

tesspbx · October 8, 2022, 9:42am

A small piece of the log during the call. A huge number of lines as under the spoiler.

RTP Debug on

[2022-10-08 16:39:15] VERBOSE[32592][C-00000179] res_rtp_asterisk.c: Got RTP packet from [2022-10-08 16:39:15] VERBOSE[32592][C-00000179] res_rtp_asterisk.c: Sent RTP packet to [2022-10-08 16:39:15] VERBOSE[32592][C-00000179] res_rtp_asterisk.c: Got RTP packet from [2022-10-08 16:39:15] VERBOSE[32592][C-00000179] res_rtp_asterisk.c: Got RTP packet from [2022-10-08 16:39:15] VERBOSE[32592][C-00000179] res_rtp_asterisk.c: Sent RTP packet to [2022-10-08 16:39:15] VERBOSE[32592][C-00000179] res_rtp_asterisk.c: Sent RTP packet to [2022-10-08 16:39:15] VERBOSE[32592][C-00000179] res_rtp_asterisk.c: Got RTP packet from [2022-10-08 16:39:15] VERBOSE[32592][C-00000179] res_rtp_asterisk.c: Got RTP packet from [2022-10-08 16:39:15] VERBOSE[32592][C-00000179] res_rtp_asterisk.c: Sent RTP packet to [2022-10-08 16:39:15] VERBOSE[32592][C-00000179] res_rtp_asterisk.c: Got RTP packet from [2022-10-08 16:39:15] VERBOSE[32592][C-00000179] res_rtp_asterisk.c: Sent RTP packet to [2022-10-08 16:39:16] VERBOSE[32592][C-00000179] res_rtp_asterisk.c: Got RTP packet from [2022-10-08 16:39:16] VERBOSE[32592][C-00000179] res_rtp_asterisk.c: Sent RTP packet to [2022-10-08 16:39:16] VERBOSE[32592][C-00000179] res_rtp_asterisk.c: Sent RTP packet to [2022-10-08 16:39:16] VERBOSE[32592][C-00000179] res_rtp_asterisk.c: Got RTP packet from [2022-10-08 16:39:16] VERBOSE[32592][C-00000179] res_rtp_asterisk.c: Got RTP packet from [2022-10-08 16:39:16] VERBOSE[32592][C-00000179] res_rtp_asterisk.c: Sent RTP packet to [2022-10-08 16:39:16] VERBOSE[32592][C-00000179] res_rtp_asterisk.c: Got RTP packet from [2022-10-08 16:39:16] VERBOSE[32592][C-00000179] res_rtp_asterisk.c: Sent RTP packet to [2022-10-08 16:39:16] VERBOSE[32592][C-00000179] res_rtp_asterisk.c: Got RTP packet from [2022-10-08 16:39:16] VERBOSE[32592][C-00000179] res_rtp_asterisk.c: Sent RTP packet to [2022-10-08 16:39:16] VERBOSE[32592][C-00000179] res_rtp_asterisk.c: Sent RTP packet to [2022-10-08 16:39:16] VERBOSE[32592][C-00000179] res_rtp_asterisk.c: Got RTP packet from [2022-10-08 16:39:16] VERBOSE[32592][C-00000179] res_rtp_asterisk.c: Sent RTP packet to [2022-10-08 16:39:16] VERBOSE[32592][C-00000179] res_rtp_asterisk.c: Got RTP packet from [2022-10-08 16:39:16] VERBOSE[32592][C-00000179] res_rtp_asterisk.c: Got RTP packet from [2022-10-08 16:39:16] VERBOSE[32592][C-00000179] res_rtp_asterisk.c: Sent RTP packet to [2022-10-08 16:39:16] VERBOSE[32592][C-00000179] res_rtp_asterisk.c: Sent RTP packet to [2022-10-08 16:39:16] VERBOSE[32592][C-00000179] res_rtp_asterisk.c: Got RTP packet from [2022-10-08 16:39:16] VERBOSE[32592][C-00000179] res_rtp_asterisk.c: Sent RTP packet to [2022-10-08 16:39:16] VERBOSE[32592][C-00000179] res_rtp_asterisk.c: Got RTP packet from [2022-10-08 16:39:16] VERBOSE[32592][C-00000179] res_rtp_asterisk.c: Got RTP packet from [2022-10-08 16:39:16] VERBOSE[32592][C-00000179] res_rtp_asterisk.c: Sent RTP packet to [2022-10-08 16:39:16] VERBOSE[32592][C-00000179] res_rtp_asterisk.c: Got RTP packet from [2022-10-08 16:39:16] VERBOSE[32592][C-00000179] res_rtp_asterisk.c: Sent RTP packet to [2022-10-08 16:39:16] VERBOSE[32592][C-00000179] res_rtp_asterisk.c: Sent RTP packet to [2022-10-08 16:39:16] VERBOSE[32592][C-00000179] res_rtp_asterisk.c: Got RTP packet from [2022-10-08 16:39:16] VERBOSE[32592][C-00000179] res_rtp_asterisk.c: Got RTP packet from [2022-10-08 16:39:16] VERBOSE[32592][C-00000179] res_rtp_asterisk.c: Sent RTP packet to [2022-10-08 16:39:16] VERBOSE[32592][C-00000179] res_rtp_asterisk.c: Sent RTP packet to [2022-10-08 16:39:16] VERBOSE[32592][C-00000179] res_rtp_asterisk.c: Got RTP packet from [2022-10-08 16:39:16] VERBOSE[32592][C-00000179] res_rtp_asterisk.c: Got RTP packet from 80.75.132.72:10686 (type 00, seq 005483, ts 13885720, len 000160)
80.75.132.72:10686 (type 00, seq 037181, ts 773760, len 000160)
80.75.132.72:10686 (type 00, seq 005484, ts 13885880, len 000160)
80.75.132.72:10686 (type 00, seq 005485, ts 13886040, len 000160)
80.75.132.72:10686 (type 00, seq 037182, ts 773920, len 000160)
80.75.132.72:10686 (type 00, seq 037183, ts 774080, len 000160)
80.75.132.72:10686 (type 00, seq 005486, ts 13886200, len 000160)
80.75.132.72:10686 (type 00, seq 005487, ts 13886360, len 000160)
80.75.132.72:10686 (type 00, seq 037184, ts 774240, len 000160)
80.75.132.72:10686 (type 00, seq 005488, ts 13886520, len 000160)
80.75.132.72:10686 (type 00, seq 037185, ts 774400, len 000160)
80.75.132.72:10686 (type 00, seq 005489, ts 13886680, len 000160)
80.75.132.72:10686 (type 00, seq 037186, ts 774560, len 000160)
80.75.132.72:10686 (type 00, seq 037187, ts 774720, len 000160)
80.75.132.72:10686 (type 00, seq 005490, ts 13886840, len 000160)
80.75.132.72:10686 (type 00, seq 005491, ts 13887000, len 000160)
80.75.132.72:10686 (type 00, seq 037188, ts 774880, len 000160)
80.75.132.72:10686 (type 00, seq 005492, ts 13887160, len 000160)
80.75.132.72:10686 (type 00, seq 037189, ts 775040, len 000160)
80.75.132.72:10686 (type 00, seq 005493, ts 13887320, len 000160)
80.75.132.72:10686 (type 00, seq 037190, ts 775200, len 000160)
80.75.132.72:10686 (type 00, seq 037191, ts 775360, len 000160)
80.75.132.72:10686 (type 00, seq 005494, ts 13887480, len 000160)
80.75.132.72:10686 (type 00, seq 037192, ts 775520, len 000160)
80.75.132.72:10686 (type 00, seq 005495, ts 13887640, len 000160)
80.75.132.72:10686 (type 00, seq 005496, ts 13887800, len 000160)
80.75.132.72:10686 (type 00, seq 037193, ts 775680, len 000160)
80.75.132.72:10686 (type 00, seq 037194, ts 775840, len 000160)
80.75.132.72:10686 (type 00, seq 005497, ts 13887960, len 000160)
80.75.132.72:10686 (type 00, seq 037195, ts 776000, len 000160)
80.75.132.72:10686 (type 00, seq 005498, ts 13888120, len 000160)
80.75.132.72:10686 (type 00, seq 005499, ts 13888280, len 000160)
80.75.132.72:10686 (type 00, seq 037196, ts 776160, len 000160)
80.75.132.72:10686 (type 00, seq 005500, ts 13888440, len 000160)
80.75.132.72:10686 (type 00, seq 037197, ts 776320, len 000160)
80.75.132.72:10686 (type 00, seq 037198, ts 776480, len 000160)
80.75.132.72:10686 (type 00, seq 005501, ts 13888600, len 000160)
80.75.132.72:10686 (type 00, seq 005502, ts 13888760, len 000160)
80.75.132.72:10686 (type 00, seq 037199, ts 776640, len 000160)
80.75.132.72:10686 (type 00, seq 037200, ts 776800, len 000160)
80.75.132.72:10686 (type 00, seq 005503, ts 13888920, len 000160)
80.75.132.72:10686 (type 00, seq 005504, ts 13889080, len 000160)

david55 · October 8, 2022, 10:13am

There is no DTMF in that last log, or at least no RFC 2833 or 4733 DTMF. If there were RFC 2833/4733 DTMF, the type wouldn’t be 00 and the length would be much less than 160. Also, you really need the full log for this, to see how the RTP correlates with the DTMF logging.

tesspbx · October 8, 2022, 10:24am

Sorry for the masked link, as a forum newbie I’m not yet allowed to upload files here and post links

pcap and full log

https://drive_google_com/file/d/1ljwkMRBj9GtnPE4s6BpNN4Xm0mMTc5_3/view?usp=sharing
https://drive_google_com/file/d/1KODXFg0UeUHiSlqRDbfvKFchpVvJsx_I/view?usp=sharing

david55 · October 8, 2022, 10:31am

You should upload to pastebin.freepbx.org and post the final part of the URL (or you can post the whole URL as preformatted text).

tesspbx · October 8, 2022, 10:35am

c516b42e

david55 · October 8, 2022, 11:01am

You should really fix this, even though Asterisk seems to have made the correct assumtpion:

[2022-10-08 12:24:16] WARNING[2711] chan_sip.c: Unknown dtmf mode 'rfc4733' on line 851, using rfc2833
[2022-10-08 12:24:16] WARNING[2711] chan_sip.c: Unknown dtmf mode 'rfc4733' on line 864, using rfc2833

Assuming this is the right call, there is no RFC 2833/4733 DTMF; it is all G.711U.

If not the right call, please indicate which of these it is:


"Start Time","Stop Time","Initial Speaker","From","To","Protocol","Duration","Packets","State","Comments"
"0.726141","32.225738","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:31","24","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"3.909180","35.409181","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:31","24","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"7.081243","38.581957","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:31","24","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"8.465983","138.539759","80.75.132.72","79825199215 <sip:[email protected]>","<sip:[email protected]:5060>","SIP","00:02:10","12","COMPLETED","INVITE 200 200"
"10.187799","41.687608","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:31","24","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"13.466251","44.966053","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:31","24","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"16.608419","48.107984","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:31","24","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"19.781948","51.281665","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:31","24","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"23.081982","54.581955","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:31","24","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"25.378496","56.877858","2.57.121.122","<sip:[email protected]>","<sip:[email protected]>","SIP","00:00:31","24","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"26.478892","57.979232","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:31","24","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"29.758979","61.258610","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:31","24","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"33.089318","64.590066","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:31","24","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"36.379011","67.879309","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:31","24","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"39.610419","71.110440","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:31","24","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"42.820999","74.321172","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:31","24","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"46.080343","77.580276","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:31","24","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"49.268584","80.768317","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:31","24","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"52.419472","83.918992","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:31","24","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"55.627230","87.126713","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:31","24","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"58.790279","90.290412","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:31","24","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"60.269166","91.769333","2.57.121.122","<sip:[email protected]>","<sip:[email protected]>","SIP","00:00:31","24","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"61.906268","93.405932","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:31","24","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"65.084634","96.584678","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:31","24","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"68.155607","99.655958","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:31","24","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"71.326232","102.826022","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:31","24","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"74.475891","105.975767","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:31","24","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"77.606474","109.106436","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:31","24","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"80.820963","112.320548","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:31","24","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"83.867676","115.367337","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:31","24","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"87.017378","118.517672","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:31","24","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"90.224149","121.724221","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:31","24","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"93.264602","124.763932","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:31","24","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"95.330400","126.830079","2.57.121.122","<sip:[email protected]>","<sip:[email protected]>","SIP","00:00:31","24","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"96.481389","127.980700","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:31","24","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"98.607144","98.607144","45.134.144.227","<sip:[email protected]>","<sip:[email protected]>","SIP","00:00:00","2","CALL SETUP","INVITE"
"99.609563","131.108975","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:31","24","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"102.755755","134.255281","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:31","24","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"105.835443","137.334947","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:31","24","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"108.968047","140.468234","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:31","24","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"112.102407","139.603087","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:27","22","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"115.233001","142.733000","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:27","22","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"118.355331","141.854864","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:23","20","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"121.549841","141.050010","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:19","18","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"121.998855","141.498308","45.93.16.164","<sip:[email protected]>","<sip:[email protected]>","SIP","00:00:19","18","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"124.699626","140.199284","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:15","16","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401 401 401"
"127.823321","139.323772","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:11","14","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401"
"130.956640","142.456337","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:11","14","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401"
"131.140157","142.639891","2.57.121.122","<sip:[email protected]>","<sip:[email protected]>","SIP","00:00:11","14","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401 401 401"
"134.064731","141.564411","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:07","12","REJECTED","INVITE 401 401 401 401 401 401 401 401 401 401"
"137.071578","140.571382","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:03","10","REJECTED","INVITE 401 401 401 401 401 401 401 401"
"140.333785","141.833763","66.23.238.6","<sip:[email protected];transport=UDP>","<sip:[email protected];transport=UDP>","SIP","00:00:01","8","REJECTED","INVITE 401 401 401 401 401 401"

tesspbx · October 8, 2022, 11:10am

Yep, I tried to switch the trunk to 4733 and did not switch back

david55:

You should really fix this, even though Asterisk seems to have made the correct assumtpion:
[2022-10-08 12:24:16] WARNING[2711] chan_sip.c: Unknown dtmf mode 'rfc4733' on line 851, using rfc2833
[2022-10-08 12:24:16] WARNING[2711] chan_sip.c: Unknown dtmf mode 'rfc4733' on line

I’ll try to turn it off

These are constant password guessing attempts. So far, I haven’t come up with anything other than a fail2ban. Right only 79825199215

tesspbx · October 8, 2022, 11:25am

I tried to leave only alaw, only 729, 729 and alaw together - nothing has changed, except that when both 711s were turned off, calls simply stopped going through . The operator does not provide any other codecs

david55 · October 8, 2022, 11:36am

I wasn’t saying turn it off; I was saying use the value that chan_sip recognizes, which is rfc2833. RFC 4733 is an enhanced version of RFC 2833, but chan_sip still uses the old name.

That call has no RFC 2833 (or 4733) DTMF, so should not register any digits.

tesspbx · October 8, 2022, 11:50am

Yes, I already understood)

Switched trunk back to 2833

Therefore, this cellular operator does not transmit? I tried now to dial from a landline phone and it worked

tesspbx · October 8, 2022, 11:55am

I will answer myself. When calling from the same mobile phone to another server in a different location, everything works out. Accordingly, dtmf reaches the server. Is there a possibility that some of the traffic may be blocked by a firewall/provider/etc?

david55 · October 8, 2022, 12:17pm

In the media, I’m seeing the incoming audio muted during the announcement, and for about 2 seconds thereafter, then some clicks, and and finally what looks like noise.

I’d suggest something is doing echo suppression by muting the audio, and it is possible that that is also clipping the digits, if they are sent in the first two or so seconds after the the announcement.

tesspbx · October 8, 2022, 3:38pm

I re-read all the configs, I found about echo cancellation only in the DAHDI settings.

The problem manifests itself only when making calls from cellular, from landlines everything works as it should. I thought maybe the problem was specifically in my phone, I asked a friend to call from another device and another cellular operator - the problem persists.
In addition, when I call freepbx servers in other places from my device (3 other servers, older ones and in other cities), everything works. The settings are identical, only trunks and extensions differ. I don’t know where else to look, what kind of nonsense is obtained

david55 · October 8, 2022, 3:57pm

I said echo suppression, not echo cancellation. Echo cancellation would not blank the audio completely, but, if you operate the connection effectively half duplex, you get quite effective echo suppression with a low tech solution.

Asterisk doesn’t do this sort of echo suppression, so it has to come from the device or the network. I would hope the device would ignore it when sending DTMF. Also, the packet capture is showing blanking of the audio before it arrives a Asterisk, so, taken together, I assume it is the network.

tesspbx · October 8, 2022, 4:12pm

Thnx, I will strain network engineer