We have been running a SIP Trunk on a Pansonic TDA30 for a while now. We are looking to replace it with Freepbx and 5 extensions. So we have setup a test trunk with our provider and i followed both their wiki and the freepbx one to set it up.
I can call out, get called and when needed via a menu the on duty phone gets called (with the original caller ID! which the TDA could not do)
But then it stopped accepting calls. Looking through the logs i could see that the Freepbx rejected those call because they came from an unknown peer. For testing i enabled the allow anonymous calls (firewall is set to only allow calls from the ip range of our SIP provider).
Calls come in but show up as the account ID and not the number that called.
Luckily i have a log with both the correct and wrong call. But i have no idea what the difference is exactly.
Note: Changed our company name to COMPANYNAME and the phone number to +0123456789
LOG
[2019-10-23 09:28:08] VERBOSE[13345][C-00000003] netsock2.c: Using SIP RTP TOS bits 184
[2019-10-23 09:28:08] VERBOSE[13345][C-00000003] netsock2.c: Using SIP RTP CoS mark 5
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [+0123456789@from-sip-external:1] NoOp(“SIP/voipgrid.nl-00000004”, “Received incoming SIP connection from unknown peer to +0123456789”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [+0123456789@from-sip-external:2] Set(“SIP/voipgrid.nl-00000004”, “DID=+0123456789”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [+0123456789@from-sip-external:3] Goto(“SIP/voipgrid.nl-00000004”, “s,1”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx_builtins.c: Goto (from-sip-external,s,1)
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@from-sip-external:1] GotoIf(“SIP/voipgrid.nl-00000004”, “1?setlanguage:checkanon”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx_builtins.c: Goto (from-sip-external,s,2)
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@from-sip-external:2] Set(“SIP/voipgrid.nl-00000004”, “CHANNEL(language)=nl”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@from-sip-external:3] GotoIf(“SIP/voipgrid.nl-00000004”, “0?noanonymous”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@from-sip-external:4] Goto(“SIP/voipgrid.nl-00000004”, “from-trunk,+0123456789,1”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx_builtins.c: Goto (from-trunk,+0123456789,1)
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [+0123456789@from-trunk:1] NoOp(“SIP/voipgrid.nl-00000004”, “Catch-All DID Match - Found +0123456789 - You probably want a DID for this.”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [+0123456789@from-trunk:2] Set(“SIP/voipgrid.nl-00000004”, “__FROM_DID=+0123456789”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [+0123456789@from-trunk:3] Goto(“SIP/voipgrid.nl-00000004”, “ext-did,s,1”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx_builtins.c: Goto (ext-did,s,1)
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@ext-did:1] Set(“SIP/voipgrid.nl-00000004”, “__DIRECTION=INBOUND”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@ext-did:2] Gosub(“SIP/voipgrid.nl-00000004”, “sub-record-check,s,1(in,s,no)”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@sub-record-check:1] GotoIf(“SIP/voipgrid.nl-00000004”, “0?initialized”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@sub-record-check:2] Set(“SIP/voipgrid.nl-00000004”, “__REC_STATUS=INITIALIZED”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@sub-record-check:3] Set(“SIP/voipgrid.nl-00000004”, “NOW=1571815688”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@sub-record-check:4] Set(“SIP/voipgrid.nl-00000004”, “__DAY=23”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@sub-record-check:5] Set(“SIP/voipgrid.nl-00000004”, “__MONTH=10”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@sub-record-check:6] Set(“SIP/voipgrid.nl-00000004”, “__YEAR=2019”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@sub-record-check:7] Set(“SIP/voipgrid.nl-00000004”, “__TIMESTR=20191023-092808”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@sub-record-check:8] Set(“SIP/voipgrid.nl-00000004”, “__FROMEXTEN=unknown”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@sub-record-check:9] Set(“SIP/voipgrid.nl-00000004”, “__MON_FMT=wav”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@sub-record-check:10] NoOp(“SIP/voipgrid.nl-00000004”, “Recordings initialized”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@sub-record-check:11] ExecIf(“SIP/voipgrid.nl-00000004”, “0?Set(ARG3=dontcare)”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@sub-record-check:12] Set(“SIP/voipgrid.nl-00000004”, “REC_POLICY_MODE_SAVE=”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@sub-record-check:13] ExecIf(“SIP/voipgrid.nl-00000004”, “0?Set(REC_STATUS=NO)”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@sub-record-check:14] GotoIf(“SIP/voipgrid.nl-00000004”, “2?checkaction”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx_builtins.c: Goto (sub-record-check,s,17)
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@sub-record-check:17] GotoIf(“SIP/voipgrid.nl-00000004”, “1?sub-record-check,in,1”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx_builtins.c: Goto (sub-record-check,in,1)
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [in@sub-record-check:1] NoOp(“SIP/voipgrid.nl-00000004”, “Inbound Recording Check to s”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [in@sub-record-check:2] Set(“SIP/voipgrid.nl-00000004”, “FROMEXTEN=unknown”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [in@sub-record-check:3] ExecIf(“SIP/voipgrid.nl-00000004”, “9?Set(FROMEXTEN=202200002)”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [in@sub-record-check:4] Gosub(“SIP/voipgrid.nl-00000004”, “recordcheck,1(no,in,s)”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp(“SIP/voipgrid.nl-00000004”, “Starting recording check against no”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [recordcheck@sub-record-check:2] Goto(“SIP/voipgrid.nl-00000004”, “no”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx_builtins.c: Goto (sub-record-check,recordcheck,12)
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [recordcheck@sub-record-check:12] Set(“SIP/voipgrid.nl-00000004”, “__REC_POLICY_MODE=NO”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [recordcheck@sub-record-check:13] Return(“SIP/voipgrid.nl-00000004”, “”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [in@sub-record-check:5] Return(“SIP/voipgrid.nl-00000004”, “”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@ext-did:3] Set(“SIP/voipgrid.nl-00000004”, “CHANNEL(tonezone)=us”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@ext-did:4] ExecIf(“SIP/voipgrid.nl-00000004”, “0?Set(__FROM_DID=s)”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@ext-did:5] Set(“SIP/voipgrid.nl-00000004”, “returnhere=1”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@ext-did:6] Gosub(“SIP/voipgrid.nl-00000004”, “app-blacklist-check,s,1()”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@app-blacklist-check:1] GotoIf(“SIP/voipgrid.nl-00000004”, “0?blacklisted”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@app-blacklist-check:2] Set(“SIP/voipgrid.nl-00000004”, “CALLED_BLACKLIST=1”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@app-blacklist-check:3] Return(“SIP/voipgrid.nl-00000004”, “”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@ext-did:7] Set(“SIP/voipgrid.nl-00000004”, “CDR(did)=+0123456789”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@ext-did:8] GotoIf(“SIP/voipgrid.nl-00000004”, “0?”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@ext-did:9] ExecIf(“SIP/voipgrid.nl-00000004”, “1 ?Set(CALLERID(name)=202200002)”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@ext-did:10] Set(“SIP/voipgrid.nl-00000004”, “CHANNEL(musicclass)=none”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@ext-did:11] Set(“SIP/voipgrid.nl-00000004”, “__MOHCLASS=none”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@ext-did:12] Set(“SIP/voipgrid.nl-00000004”, “__REVERSAL_REJECT=FALSE”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@ext-did:13] GotoIf(“SIP/voipgrid.nl-00000004”, “1?post-reverse-charge”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx_builtins.c: Goto (ext-did,s,15)
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@ext-did:15] NoOp(“SIP/voipgrid.nl-00000004”, “”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@ext-did:16] Set(“SIP/voipgrid.nl-00000004”, “__CALLINGNAMEPRES_SV=allowed_not_screened”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@ext-did:17] Set(“SIP/voipgrid.nl-00000004”, “__CALLINGNUMPRES_SV=allowed_not_screened”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@ext-did:18] Set(“SIP/voipgrid.nl-00000004”, “CALLERID(name-pres)=allowed_not_screened”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@ext-did:19] Set(“SIP/voipgrid.nl-00000004”, “CALLERID(num-pres)=allowed_not_screened”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@ext-did:20] NoOp(“SIP/voipgrid.nl-00000004”, “CallerID Entry Point”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@ext-did:21] Set(“SIP/voipgrid.nl-00000004”, “__CRM_DIRECTION=INBOUND”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@ext-did:22] Set(“SIP/voipgrid.nl-00000004”, “__CRM_SOURCE=202200002”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@ext-did:23] Set(“SIP/voipgrid.nl-00000004”, “__CRM_LINKEDID=1571815688.4”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@ext-did:24] ExecIf(“SIP/voipgrid.nl-00000004”, “1?Set(CHANNEL(hangup_handler_push)=crm-hangup,s,1)”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@ext-did:25] Goto(“SIP/voipgrid.nl-00000004”, “ivr-1,s,1”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx_builtins.c: Goto (ivr-1,s,1)
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@ivr-1:1] Set(“SIP/voipgrid.nl-00000004”, “TIMEOUT_LOOPCOUNT=0”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@ivr-1:2] Set(“SIP/voipgrid.nl-00000004”, “INVALID_LOOPCOUNT=0”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@ivr-1:3] Set(“SIP/voipgrid.nl-00000004”, “_IVR_CONTEXT_ivr-1=”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@ivr-1:4] Set(“SIP/voipgrid.nl-00000004”, “_IVR_CONTEXT=ivr-1”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@ivr-1:5] Set(“SIP/voipgrid.nl-00000004”, “__IVR_RETVM=”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@ivr-1:6] GotoIf(“SIP/voipgrid.nl-00000004”, “0?skip”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@ivr-1:7] Answer(“SIP/voipgrid.nl-00000004”, “”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@ivr-1:8] Set(“SIP/voipgrid.nl-00000004”, “IVR_MSG=custom/test”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@ivr-1:9] Set(“SIP/voipgrid.nl-00000004”, “DIGITS=”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@ivr-1:10] Set(“SIP/voipgrid.nl-00000004”, “IVREXT=”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@ivr-1:11] Set(“SIP/voipgrid.nl-00000004”, “NODEFOUND=0”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@ivr-1:12] Set(“SIP/voipgrid.nl-00000004”, “LOCALEXT=0”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@ivr-1:13] Set(“SIP/voipgrid.nl-00000004”, “DIREXT=0”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@ivr-1:14] ExecIf(“SIP/voipgrid.nl-00000004”, “0?Set(DIGITS=)”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@ivr-1:15] While(“SIP/voipgrid.nl-00000004”, "1 ") in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] pbx.c: Executing [s@ivr-1:16] Read(“SIP/voipgrid.nl-00000004”, “IVREXT,custom/test,1,0,0”) in new stack
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] app_read.c: Accepting a maximum of 1 digits.
[2019-10-23 09:28:08] VERBOSE[21015][C-00000003] file.c: <SIP/voipgrid.nl-00000004> Playing ‘custom/test.slin’ (language ‘nl’)
[2019-10-23 09:28:10] VERBOSE[12968] asterisk.c: Remote UNIX connection
[2019-10-23 09:28:10] VERBOSE[21130] asterisk.c: Remote UNIX connection disconnected
[2019-10-23 09:28:10] VERBOSE[12968] asterisk.c: Remote UNIX connection
[2019-10-23 09:28:10] VERBOSE[21132] asterisk.c: Remote UNIX connection disconnected
[2019-10-23 09:28:10] VERBOSE[12968] asterisk.c: Remote UNIX connection
[2019-10-23 09:28:10] VERBOSE[21134] asterisk.c: Remote UNIX connection disconnected
[2019-10-23 09:28:14] VERBOSE[21015][C-00000003] app_read.c: User disconnected
[2019-10-23 09:28:14] VERBOSE[21015][C-00000003] pbx.c: Executing [h@ivr-1:1] Hangup(“SIP/voipgrid.nl-00000004”, “”) in new stack
[2019-10-23 09:28:14] VERBOSE[21015][C-00000003] pbx.c: Spawn extension (ivr-1, h, 1) exited non-zero on ‘SIP/voipgrid.nl-00000004’
[2019-10-23 09:28:14] VERBOSE[21015][C-00000003] app_stack.c: SIP/voipgrid.nl-00000004 Internal Gosub(crm-hangup,s,1) start
[2019-10-23 09:28:14] VERBOSE[21015][C-00000003] pbx.c: Executing [s@crm-hangup:1] NoOp(“SIP/voipgrid.nl-00000004”, “Sending Hangup to CRM”) in new stack
[2019-10-23 09:28:14] VERBOSE[21015][C-00000003] pbx.c: Executing [s@crm-hangup:2] NoOp(“SIP/voipgrid.nl-00000004”, “HANGUP CAUSE: 16”) in new stack
[2019-10-23 09:28:14] VERBOSE[21015][C-00000003] pbx.c: Executing [s@crm-hangup:3] ExecIf(“SIP/voipgrid.nl-00000004”, “0?Set(__CRM_VOICEMAIL=)”) in new stack
[2019-10-23 09:28:14] VERBOSE[21015][C-00000003] pbx.c: Executing [s@crm-hangup:4] NoOp(“SIP/voipgrid.nl-00000004”, “MASTER CHANNEL: 1571815688.4 = 1571815688.4”) in new stack
[2019-10-23 09:28:14] VERBOSE[21015][C-00000003] pbx.c: Executing [s@crm-hangup:5] GotoIf(“SIP/voipgrid.nl-00000004”, “0?return”) in new stack
[2019-10-23 09:28:14] VERBOSE[21015][C-00000003] pbx.c: Executing [s@crm-hangup:6] Set(“SIP/voipgrid.nl-00000004”, “__CRM_HANGUP=1”) in new stack
[2019-10-23 09:28:14] VERBOSE[21015][C-00000003] pbx.c: Executing [s@crm-hangup:7] AGI(“SIP/voipgrid.nl-00000004”, “sangomacrm.agi”) in new stack
[2019-10-23 09:28:14] VERBOSE[21015][C-00000003] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/sangomacrm.agi
[2019-10-23 09:28:14] VERBOSE[21015][C-00000003] res_agi.c: <SIP/voipgrid.nl-00000004>AGI Script sangomacrm.agi completed, returning 0
[2019-10-23 09:28:14] VERBOSE[21015][C-00000003] pbx.c: Executing [s@crm-hangup:8] Return(“SIP/voipgrid.nl-00000004”, “”) in new stack
[2019-10-23 09:28:14] VERBOSE[21015][C-00000003] app_stack.c: Spawn extension (ivr-1, h, 1) exited non-zero on ‘SIP/voipgrid.nl-00000004’
[2019-10-23 09:28:14] VERBOSE[21015][C-00000003] app_stack.c: SIP/voipgrid.nl-00000004 Internal Gosub(crm-hangup,s,1) complete GOSUB_RETVAL=
[2019-10-23 09:34:42] VERBOSE[13345][C-00000004] netsock2.c: Using SIP RTP TOS bits 184
[2019-10-23 09:34:42] VERBOSE[13345][C-00000004] netsock2.c: Using SIP RTP CoS mark 5
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [+0123456789@from-trunk-sip-COMPANYNAME_SIPTRUNK:1] Set(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “GROUP()=OUT_1”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [+0123456789@from-trunk-sip-COMPANYNAME_SIPTRUNK:2] Goto(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “from-trunk,+0123456789,1”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx_builtins.c: Goto (from-trunk,+0123456789,1)
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [+0123456789@from-trunk:1] NoOp(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “Catch-All DID Match - Found +0123456789 - You probably want a DID for this.”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [+0123456789@from-trunk:2] Set(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “__FROM_DID=+0123456789”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [+0123456789@from-trunk:3] Goto(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “ext-did,s,1”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx_builtins.c: Goto (ext-did,s,1)
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@ext-did:1] Set(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “__DIRECTION=INBOUND”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@ext-did:2] Gosub(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “sub-record-check,s,1(in,s,no)”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@sub-record-check:1] GotoIf(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “0?initialized”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@sub-record-check:2] Set(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “__REC_STATUS=INITIALIZED”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@sub-record-check:3] Set(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “NOW=1571816082”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@sub-record-check:4] Set(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “__DAY=23”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@sub-record-check:5] Set(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “__MONTH=10”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@sub-record-check:6] Set(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “__YEAR=2019”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@sub-record-check:7] Set(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “__TIMESTR=20191023-093442”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@sub-record-check:8] Set(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “__FROMEXTEN=unknown”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@sub-record-check:9] Set(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “__MON_FMT=wav”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@sub-record-check:10] NoOp(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “Recordings initialized”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@sub-record-check:11] ExecIf(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “0?Set(ARG3=dontcare)”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@sub-record-check:12] Set(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “REC_POLICY_MODE_SAVE=”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@sub-record-check:13] ExecIf(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “0?Set(REC_STATUS=NO)”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@sub-record-check:14] GotoIf(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “2?checkaction”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx_builtins.c: Goto (sub-record-check,s,17)
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@sub-record-check:17] GotoIf(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “1?sub-record-check,in,1”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx_builtins.c: Goto (sub-record-check,in,1)
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [in@sub-record-check:1] NoOp(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “Inbound Recording Check to s”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [in@sub-record-check:2] Set(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “FROMEXTEN=unknown”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [in@sub-record-check:3] ExecIf(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “12?Set(FROMEXTEN=+31628776339)”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [in@sub-record-check:4] Gosub(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “recordcheck,1(no,in,s)”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “Starting recording check against no”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [recordcheck@sub-record-check:2] Goto(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “no”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx_builtins.c: Goto (sub-record-check,recordcheck,12)
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [recordcheck@sub-record-check:12] Set(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “__REC_POLICY_MODE=NO”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [recordcheck@sub-record-check:13] Return(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [in@sub-record-check:5] Return(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@ext-did:3] Set(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “CHANNEL(tonezone)=us”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@ext-did:4] ExecIf(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “0?Set(__FROM_DID=s)”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@ext-did:5] Set(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “returnhere=1”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@ext-did:6] Gosub(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “app-blacklist-check,s,1()”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@app-blacklist-check:1] GotoIf(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “0?blacklisted”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@app-blacklist-check:2] Set(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “CALLED_BLACKLIST=1”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@app-blacklist-check:3] Return(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@ext-did:7] Set(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “CDR(did)=+0123456789”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@ext-did:8] GotoIf(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “0?”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@ext-did:9] ExecIf(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “1 ?Set(CALLERID(name)=+31628776339)”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@ext-did:10] Set(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “CHANNEL(musicclass)=none”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@ext-did:11] Set(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “__MOHCLASS=none”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@ext-did:12] Set(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “__REVERSAL_REJECT=FALSE”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@ext-did:13] GotoIf(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “1?post-reverse-charge”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx_builtins.c: Goto (ext-did,s,15)
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@ext-did:15] NoOp(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@ext-did:16] Set(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “__CALLINGNAMEPRES_SV=allowed_not_screened”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@ext-did:17] Set(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “__CALLINGNUMPRES_SV=allowed_not_screened”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@ext-did:18] Set(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “CALLERID(name-pres)=allowed_not_screened”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@ext-did:19] Set(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “CALLERID(num-pres)=allowed_not_screened”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@ext-did:20] NoOp(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “CallerID Entry Point”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@ext-did:21] Set(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “__CRM_DIRECTION=INBOUND”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@ext-did:22] Set(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “__CRM_SOURCE=+31628776339”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@ext-did:23] Set(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “__CRM_LINKEDID=1571816082.5”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@ext-did:24] ExecIf(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “1?Set(CHANNEL(hangup_handler_push)=crm-hangup,s,1)”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@ext-did:25] Goto(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “ivr-1,s,1”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx_builtins.c: Goto (ivr-1,s,1)
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@ivr-1:1] Set(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “TIMEOUT_LOOPCOUNT=0”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@ivr-1:2] Set(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “INVALID_LOOPCOUNT=0”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@ivr-1:3] Set(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “_IVR_CONTEXT_ivr-1=”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@ivr-1:4] Set(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “_IVR_CONTEXT=ivr-1”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@ivr-1:5] Set(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “__IVR_RETVM=”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@ivr-1:6] GotoIf(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “0?skip”) in new stack
[2019-10-23 09:34:42] VERBOSE[21923][C-00000004] pbx.c: Executing [s@ivr-1:7] Answer(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “”) in new stack
[2019-10-23 09:34:43] VERBOSE[21923][C-00000004] pbx.c: Executing [s@ivr-1:8] Set(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “IVR_MSG=custom/test”) in new stack
[2019-10-23 09:34:43] VERBOSE[21923][C-00000004] pbx.c: Executing [s@ivr-1:9] Set(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “DIGITS=”) in new stack
[2019-10-23 09:34:43] VERBOSE[21923][C-00000004] pbx.c: Executing [s@ivr-1:10] Set(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “IVREXT=”) in new stack
[2019-10-23 09:34:43] VERBOSE[21923][C-00000004] pbx.c: Executing [s@ivr-1:11] Set(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “NODEFOUND=0”) in new stack
[2019-10-23 09:34:43] VERBOSE[21923][C-00000004] pbx.c: Executing [s@ivr-1:12] Set(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “LOCALEXT=0”) in new stack
[2019-10-23 09:34:43] VERBOSE[21923][C-00000004] pbx.c: Executing [s@ivr-1:13] Set(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “DIREXT=0”) in new stack
[2019-10-23 09:34:43] VERBOSE[21923][C-00000004] pbx.c: Executing [s@ivr-1:14] ExecIf(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “0?Set(DIGITS=)”) in new stack
[2019-10-23 09:34:43] VERBOSE[21923][C-00000004] pbx.c: Executing [s@ivr-1:15] While(“SIP/COMPANYNAME_SIPTRUNK-00000005”, "1 ") in new stack
[2019-10-23 09:34:43] VERBOSE[21923][C-00000004] pbx.c: Executing [s@ivr-1:16] Read(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “IVREXT,custom/test,1,0,0”) in new stack
[2019-10-23 09:34:43] VERBOSE[21923][C-00000004] app_read.c: Accepting a maximum of 1 digits.
[2019-10-23 09:34:43] VERBOSE[21923][C-00000004] file.c: <SIP/COMPANYNAME_SIPTRUNK-00000005> Playing ‘custom/test.slin’ (language ‘nl’)
[2019-10-23 09:34:47] VERBOSE[21923][C-00000004] app_read.c: User disconnected
[2019-10-23 09:34:47] VERBOSE[21923][C-00000004] pbx.c: Executing [h@ivr-1:1] Hangup(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “”) in new stack
[2019-10-23 09:34:47] VERBOSE[21923][C-00000004] pbx.c: Spawn extension (ivr-1, h, 1) exited non-zero on ‘SIP/COMPANYNAME_SIPTRUNK-00000005’
[2019-10-23 09:34:47] VERBOSE[21923][C-00000004] app_stack.c: SIP/COMPANYNAME_SIPTRUNK-00000005 Internal Gosub(crm-hangup,s,1) start
[2019-10-23 09:34:47] VERBOSE[21923][C-00000004] pbx.c: Executing [s@crm-hangup:1] NoOp(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “Sending Hangup to CRM”) in new stack
[2019-10-23 09:34:47] VERBOSE[21923][C-00000004] pbx.c: Executing [s@crm-hangup:2] NoOp(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “HANGUP CAUSE: 16”) in new stack
[2019-10-23 09:34:47] VERBOSE[21923][C-00000004] pbx.c: Executing [s@crm-hangup:3] ExecIf(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “0?Set(__CRM_VOICEMAIL=)”) in new stack
[2019-10-23 09:34:47] VERBOSE[21923][C-00000004] pbx.c: Executing [s@crm-hangup:4] NoOp(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “MASTER CHANNEL: 1571816082.5 = 1571816082.5”) in new stack
[2019-10-23 09:34:47] VERBOSE[21923][C-00000004] pbx.c: Executing [s@crm-hangup:5] GotoIf(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “0?return”) in new stack
[2019-10-23 09:34:47] VERBOSE[21923][C-00000004] pbx.c: Executing [s@crm-hangup:6] Set(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “__CRM_HANGUP=1”) in new stack
[2019-10-23 09:34:47] VERBOSE[21923][C-00000004] pbx.c: Executing [s@crm-hangup:7] AGI(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “sangomacrm.agi”) in new stack
[2019-10-23 09:34:47] VERBOSE[21923][C-00000004] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/sangomacrm.agi
[2019-10-23 09:34:48] VERBOSE[21923][C-00000004] res_agi.c: <SIP/COMPANYNAME_SIPTRUNK-00000005>AGI Script sangomacrm.agi completed, returning 0
[2019-10-23 09:34:48] VERBOSE[21923][C-00000004] pbx.c: Executing [s@crm-hangup:8] Return(“SIP/COMPANYNAME_SIPTRUNK-00000005”, “”) in new stack
[2019-10-23 09:34:48] VERBOSE[21923][C-00000004] app_stack.c: Spawn extension (ivr-1, h, 1) exited non-zero on ‘SIP/COMPANYNAME_SIPTRUNK-00000005’
[2019-10-23 09:34:48] VERBOSE[21923][C-00000004] app_stack.c: SIP/COMPANYNAME_SIPTRUNK-00000005 Internal Gosub(crm-hangup,s,1) complete GOSUB_RETVAL=