freePBX trunk to inbound route works - for about 20 seconds only

jacksm · March 27, 2019, 2:21pm

Hands up - this is my first attempt at anything PBX.
My Unix / Linux skills are pretty good.

I suspect using VirtualBox is a complication here but I wanted to experiment before spending on hardware / software.

I’m actually on my 3rd VirtualBox and freePBX install now. All 3 have connected fine (via CHAN_SIP) to my voipfone account and can make outgoing calls. Unfortunately all 3 also have the same problem with Inbound calls.

The problem is a weird one and not one I can find reported anywhere else… Inbound calls are routed very simply through CHAN_SIP to a custom destination in extensions_custom.conf

Following a fwconsole restart or even just following an “Apply Config” change from the freePBX gui, calls are routed correctly to my custom destination… but only for about 20 seconds!

After 20 seconds freePBX seems to disconnect (any current calls can continue) and no longer picks up on Inbound Routes. The caller gets a “The person you called is currently unavailable voicemail prompt”.

It doesn’t matter whether the custom destination has received none, one or many calls in that 20 seconds… it always disconnects after that.

I haven’t been able to find anything in the logs to indicate what is going on but of course I don’t know what I don’t know!

I suspect a firewall issue in the router, windows host, virtualbox or linux. I’ve messed around with opening up the ports, putting in DMZ, disabling firewall etc. etc. so if it IS firewall related I don’t know how to solve it.

I’ve had a few sleepless nights already. I may be being thick but I HAVE tried!

NB: The “20 seconds” is an average. Sometimes it’s zero (can’t get a call to be picked up by PBX), sometimes it’s a few seconds, it’s never laster more than about 40 seconds.

david551 · March 27, 2019, 2:26pm

You need to provide logging. Also extensions.conf doesn’t contain destinations.

jacksm · March 27, 2019, 2:48pm

I said extensions_custom.conf that contains my destination.

I’m using the “Hello, It’s Lenny” test case to see if I can get things going. I have put my “destination” (sorry if wrong word) in extensions_custom.conf
[Lenny]
exten => talk,1,Set(i={IF([“0${i}”=“016”]?7:[0{i}+1])})
same => n,ExecIf([{i}=1]?MixMonitor({UNIQUEID}.wav)) same => n,Playback(Lenny/Lenny{i})
same => n,BackgroundDetect(Lenny/backgroundnoise,1500)

I can’t upload log files (policy for new users?) so I’ve pasted in here the highlights / lowlights of /var/log/asterisk/full
If you can think what logs to target I’ll happily provide more.

full (tail 100 lines)
[2019-03-27 13:46:22] VERBOSE[26011][C-00000011] pbx.c: Executing [30210220@from-pstn:16] NoOp(“SIP/Voipfone_SIP-00000011”, “CallerID Entry Point”) in new stack
[2019-03-27 13:46:22] VERBOSE[26011][C-00000011] pbx.c: Executing [30210220@from-pstn:17] Set(“SIP/Voipfone_SIP-00000011”, “__CRM_DIRECTION=INBOUND”) in new stack
[2019-03-27 13:46:22] VERBOSE[26011][C-00000011] pbx.c: Executing [30210220@from-pstn:18] Set(“SIP/Voipfone_SIP-00000011”, “__CRM_SOURCE=07951408560”) in new stack
[2019-03-27 13:46:22] VERBOSE[26011][C-00000011] pbx.c: Executing [30210220@from-pstn:19] Set(“SIP/Voipfone_SIP-00000011”, “__CRM_LINKEDID=1553694382.17”) in new stack
[2019-03-27 13:46:22] VERBOSE[26011][C-00000011] pbx.c: Executing [30210220@from-pstn:20] ExecIf(“SIP/Voipfone_SIP-00000011”, “1?Set(CHANNEL(hangup_handler_push)=crm-hangup,s,1)”) in new stack
[2019-03-27 13:46:22] VERBOSE[26011][C-00000011] pbx.c: Executing [30210220@from-pstn:21] Goto(“SIP/Voipfone_SIP-00000011”, “Lenny,talk,1”) in new stack
[2019-03-27 13:46:22] VERBOSE[26011][C-00000011] pbx_builtins.c: Goto (Lenny,talk,1)
[2019-03-27 13:46:22] VERBOSE[26011][C-00000011] pbx.c: Executing [talk@Lenny:1] Set(“SIP/Voipfone_SIP-00000011”, “i=1”) in new stack
[2019-03-27 13:46:22] VERBOSE[26011][C-00000011] pbx.c: Executing [talk@Lenny:2] ExecIf(“SIP/Voipfone_SIP-00000011”, “1?MixMonitor(1553694382.17.wav)”) in new stack
[2019-03-27 13:46:22] VERBOSE[26013][C-00000011] app_mixmonitor.c: Begin MixMonitor Recording SIP/Voipfone_SIP-00000011
[2019-03-27 13:46:22] VERBOSE[26011][C-00000011] pbx.c: Executing [talk@Lenny:3] Playback(“SIP/Voipfone_SIP-00000011”, “Lenny/Lenny1”) in new stack
[2019-03-27 13:46:22] VERBOSE[26011][C-00000011] file.c: <SIP/Voipfone_SIP-00000011> Playing ‘Lenny/Lenny1.ulaw’ (language ‘en’)
[2019-03-27 13:46:26] VERBOSE[26011][C-00000011] app_stack.c: SIP/Voipfone_SIP-00000011 Internal Gosub(crm-hangup,s,1) start
[2019-03-27 13:46:26] VERBOSE[26011][C-00000011] pbx.c: Executing [s@crm-hangup:1] NoOp(“SIP/Voipfone_SIP-00000011”, “Sending Hangup to CRM”) in new stack
[2019-03-27 13:46:26] VERBOSE[26011][C-00000011] pbx.c: Executing [s@crm-hangup:2] NoOp(“SIP/Voipfone_SIP-00000011”, “HANGUP CAUSE: 0”) in new stack
[2019-03-27 13:46:26] VERBOSE[26011][C-00000011] pbx.c: Executing [s@crm-hangup:3] ExecIf(“SIP/Voipfone_SIP-00000011”, “0?Set(__CRM_VOICEMAIL=)”) in new stack
[2019-03-27 13:46:26] VERBOSE[26011][C-00000011] pbx.c: Executing [s@crm-hangup:4] NoOp(“SIP/Voipfone_SIP-00000011”, “MASTER CHANNEL: 1553694382.17 = 1553694382.17”) in new stack
[2019-03-27 13:46:26] VERBOSE[26011][C-00000011] pbx.c: Executing [s@crm-hangup:5] GotoIf(“SIP/Voipfone_SIP-00000011”, “0?return”) in new stack
[2019-03-27 13:46:26] VERBOSE[26011][C-00000011] pbx.c: Executing [s@crm-hangup:6] Set(“SIP/Voipfone_SIP-00000011”, “__CRM_HANGUP=1”) in new stack
[2019-03-27 13:46:26] VERBOSE[26011][C-00000011] pbx.c: Executing [s@crm-hangup:7] AGI(“SIP/Voipfone_SIP-00000011”, “sangomacrm.agi”) in new stack
[2019-03-27 13:46:26] VERBOSE[26011][C-00000011] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/sangomacrm.agi
[2019-03-27 13:46:26] VERBOSE[26011][C-00000011] res_agi.c: <SIP/Voipfone_SIP-00000011>AGI Script sangomacrm.agi completed, returning 0
[2019-03-27 13:46:26] VERBOSE[26011][C-00000011] pbx.c: Executing [s@crm-hangup:8] Return(“SIP/Voipfone_SIP-00000011”, “”) in new stack
[2019-03-27 13:46:26] VERBOSE[26011][C-00000011] app_stack.c: Spawn extension (Lenny, talk, 3) exited non-zero on ‘SIP/Voipfone_SIP-00000011’
[2019-03-27 13:46:26] VERBOSE[26011][C-00000011] app_stack.c: SIP/Voipfone_SIP-00000011 Internal Gosub(crm-hangup,s,1) complete GOSUB_RETVAL=
[2019-03-27 13:46:26] VERBOSE[26013][C-00000011] app_mixmonitor.c: MixMonitor close filestream (mixed)
[2019-03-27 13:46:26] VERBOSE[26013][C-00000011] app_mixmonitor.c: End MixMonitor Recording SIP/Voipfone_SIP-00000011
[2019-03-27 13:46:30] VERBOSE[2127][C-00000012] netsock2.c: Using SIP RTP TOS bits 184
[2019-03-27 13:46:30] VERBOSE[2127][C-00000012] netsock2.c: Using SIP RTP CoS mark 5
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [30210220@from-pstn:1] Set(“SIP/Voipfone_SIP-00000012”, “__DIRECTION=INBOUND”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [30210220@from-pstn:2] Gosub(“SIP/Voipfone_SIP-00000012”, “sub-record-check,s,1(in,30210220,dontcare)”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [s@sub-record-check:1] GotoIf(“SIP/Voipfone_SIP-00000012”, “0?initialized”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [s@sub-record-check:2] Set(“SIP/Voipfone_SIP-00000012”, “__REC_STATUS=INITIALIZED”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [s@sub-record-check:3] Set(“SIP/Voipfone_SIP-00000012”, “NOW=1553694390”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [s@sub-record-check:4] Set(“SIP/Voipfone_SIP-00000012”, “__DAY=27”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [s@sub-record-check:5] Set(“SIP/Voipfone_SIP-00000012”, “__MONTH=03”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [s@sub-record-check:6] Set(“SIP/Voipfone_SIP-00000012”, “__YEAR=2019”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [s@sub-record-check:7] Set(“SIP/Voipfone_SIP-00000012”, “__TIMESTR=20190327-134630”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [s@sub-record-check:8] Set(“SIP/Voipfone_SIP-00000012”, “__FROMEXTEN=unknown”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [s@sub-record-check:9] Set(“SIP/Voipfone_SIP-00000012”, “__MON_FMT=wav”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [s@sub-record-check:10] NoOp(“SIP/Voipfone_SIP-00000012”, “Recordings initialized”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [s@sub-record-check:11] ExecIf(“SIP/Voipfone_SIP-00000012”, “0?Set(ARG3=dontcare)”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [s@sub-record-check:12] Set(“SIP/Voipfone_SIP-00000012”, “REC_POLICY_MODE_SAVE=”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [s@sub-record-check:13] ExecIf(“SIP/Voipfone_SIP-00000012”, “0?Set(REC_STATUS=NO)”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [s@sub-record-check:14] GotoIf(“SIP/Voipfone_SIP-00000012”, “2?checkaction”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx_builtins.c: Goto (sub-record-check,s,17)
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [s@sub-record-check:17] GotoIf(“SIP/Voipfone_SIP-00000012”, “1?sub-record-check,in,1”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx_builtins.c: Goto (sub-record-check,in,1)
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [in@sub-record-check:1] NoOp(“SIP/Voipfone_SIP-00000012”, “Inbound Recording Check to 30210220”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [in@sub-record-check:2] Set(“SIP/Voipfone_SIP-00000012”, “FROMEXTEN=unknown”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [in@sub-record-check:3] ExecIf(“SIP/Voipfone_SIP-00000012”, “11?Set(FROMEXTEN=07951408560)”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [in@sub-record-check:4] Gosub(“SIP/Voipfone_SIP-00000012”, “recordcheck,1(dontcare,in,30210220)”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp(“SIP/Voipfone_SIP-00000012”, “Starting recording check against dontcare”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [recordcheck@sub-record-check:2] Goto(“SIP/Voipfone_SIP-00000012”, “dontcare”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [recordcheck@sub-record-check:3] Return(“SIP/Voipfone_SIP-00000012”, “”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [in@sub-record-check:5] Return(“SIP/Voipfone_SIP-00000012”, “”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [30210220@from-pstn:3] Gosub(“SIP/Voipfone_SIP-00000012”, “app-blacklist-check,s,1()”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [s@app-blacklist-check:1] GotoIf(“SIP/Voipfone_SIP-00000012”, “0?blacklisted”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [s@app-blacklist-check:2] Set(“SIP/Voipfone_SIP-00000012”, “CALLED_BLACKLIST=1”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [s@app-blacklist-check:3] Return(“SIP/Voipfone_SIP-00000012”, “”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [30210220@from-pstn:4] Set(“SIP/Voipfone_SIP-00000012”, “__FROM_DID=30210220”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [30210220@from-pstn:5] Set(“SIP/Voipfone_SIP-00000012”, “CDR(did)=30210220”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [30210220@from-pstn:6] ExecIf(“SIP/Voipfone_SIP-00000012”, “0 ?Set(CALLERID(name)=07951408560)”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [30210220@from-pstn:7] Set(“SIP/Voipfone_SIP-00000012”, “__MOHCLASS=”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [30210220@from-pstn:8] Set(“SIP/Voipfone_SIP-00000012”, “__REVERSAL_REJECT=FALSE”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [30210220@from-pstn:9] GotoIf(“SIP/Voipfone_SIP-00000012”, “1?post-reverse-charge”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx_builtins.c: Goto (from-pstn,30210220,11)
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [30210220@from-pstn:11] NoOp(“SIP/Voipfone_SIP-00000012”, “”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [30210220@from-pstn:12] Set(“SIP/Voipfone_SIP-00000012”, “__CALLINGNAMEPRES_SV=allowed_not_screened”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [30210220@from-pstn:13] Set(“SIP/Voipfone_SIP-00000012”, “__CALLINGNUMPRES_SV=allowed_not_screened”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [30210220@from-pstn:14] Set(“SIP/Voipfone_SIP-00000012”, “CALLERID(name-pres)=allowed_not_screened”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [30210220@from-pstn:15] Set(“SIP/Voipfone_SIP-00000012”, “CALLERID(num-pres)=allowed_not_screened”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [30210220@from-pstn:16] NoOp(“SIP/Voipfone_SIP-00000012”, “CallerID Entry Point”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [30210220@from-pstn:17] Set(“SIP/Voipfone_SIP-00000012”, “__CRM_DIRECTION=INBOUND”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [30210220@from-pstn:18] Set(“SIP/Voipfone_SIP-00000012”, “__CRM_SOURCE=07951408560”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [30210220@from-pstn:19] Set(“SIP/Voipfone_SIP-00000012”, “__CRM_LINKEDID=1553694390.18”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [30210220@from-pstn:20] ExecIf(“SIP/Voipfone_SIP-00000012”, “1?Set(CHANNEL(hangup_handler_push)=crm-hangup,s,1)”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [30210220@from-pstn:21] Goto(“SIP/Voipfone_SIP-00000012”, “Lenny,talk,1”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx_builtins.c: Goto (Lenny,talk,1)
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [talk@Lenny:1] Set(“SIP/Voipfone_SIP-00000012”, “i=1”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [talk@Lenny:2] ExecIf(“SIP/Voipfone_SIP-00000012”, “1?MixMonitor(1553694390.18.wav)”) in new stack
[2019-03-27 13:46:30] VERBOSE[26052][C-00000012] pbx.c: Executing [talk@Lenny:3] Playback(“SIP/Voipfone_SIP-00000012”, “Lenny/Lenny1”) in new stack
[2019-03-27 13:46:30] VERBOSE[26053][C-00000012] app_mixmonitor.c: Begin MixMonitor Recording SIP/Voipfone_SIP-00000012
[2019-03-27 13:46:31] VERBOSE[26052][C-00000012] file.c: <SIP/Voipfone_SIP-00000012> Playing ‘Lenny/Lenny1.ulaw’ (language ‘en’)
[2019-03-27 13:46:35] VERBOSE[26052][C-00000012] app_stack.c: SIP/Voipfone_SIP-00000012 Internal Gosub(crm-hangup,s,1) start
[2019-03-27 13:46:35] VERBOSE[26052][C-00000012] pbx.c: Executing [s@crm-hangup:1] NoOp(“SIP/Voipfone_SIP-00000012”, “Sending Hangup to CRM”) in new stack
[2019-03-27 13:46:35] VERBOSE[26052][C-00000012] pbx.c: Executing [s@crm-hangup:2] NoOp(“SIP/Voipfone_SIP-00000012”, “HANGUP CAUSE: 0”) in new stack
[2019-03-27 13:46:35] VERBOSE[26052][C-00000012] pbx.c: Executing [s@crm-hangup:3] ExecIf(“SIP/Voipfone_SIP-00000012”, “0?Set(__CRM_VOICEMAIL=)”) in new stack
[2019-03-27 13:46:35] VERBOSE[26052][C-00000012] pbx.c: Executing [s@crm-hangup:4] NoOp(“SIP/Voipfone_SIP-00000012”, “MASTER CHANNEL: 1553694390.18 = 1553694390.18”) in new stack
[2019-03-27 13:46:35] VERBOSE[26052][C-00000012] pbx.c: Executing [s@crm-hangup:5] GotoIf(“SIP/Voipfone_SIP-00000012”, “0?return”) in new stack
[2019-03-27 13:46:35] VERBOSE[26052][C-00000012] pbx.c: Executing [s@crm-hangup:6] Set(“SIP/Voipfone_SIP-00000012”, “__CRM_HANGUP=1”) in new stack
[2019-03-27 13:46:35] VERBOSE[26052][C-00000012] pbx.c: Executing [s@crm-hangup:7] AGI(“SIP/Voipfone_SIP-00000012”, “sangomacrm.agi”) in new stack
[2019-03-27 13:46:35] VERBOSE[26052][C-00000012] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/sangomacrm.agi
[2019-03-27 13:46:35] VERBOSE[26052][C-00000012] res_agi.c: <SIP/Voipfone_SIP-00000012>AGI Script sangomacrm.agi completed, returning 0
[2019-03-27 13:46:35] VERBOSE[26052][C-00000012] pbx.c: Executing [s@crm-hangup:8] Return(“SIP/Voipfone_SIP-00000012”, “”) in new stack
[2019-03-27 13:46:35] VERBOSE[26052][C-00000012] app_stack.c: Spawn extension (Lenny, talk, 3) exited non-zero on ‘SIP/Voipfone_SIP-00000012’
[2019-03-27 13:46:35] VERBOSE[26052][C-00000012] app_stack.c: SIP/Voipfone_SIP-00000012 Internal Gosub(crm-hangup,s,1) complete GOSUB_RETVAL=
[2019-03-27 13:46:35] VERBOSE[26053][C-00000012] app_mixmonitor.c: MixMonitor close filestream (mixed)
[2019-03-27 13:46:35] VERBOSE[26053][C-00000012] app_mixmonitor.c: End MixMonitor Recording SIP/Voipfone_SIP-00000012

full (last 100 ERRORS)
[2019-03-27 10:43:16] ERROR[25137] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:43:16] ERROR[25137] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:43:41] ERROR[25469] config_options.c: Unable to load config file ‘acl.conf’
[2019-03-27 10:43:41] ERROR[25469] res_sorcery_config.c: Unable to load config file ‘pjproject.conf’
[2019-03-27 10:43:41] ERROR[25148] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:43:41] ERROR[25148] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:43:41] ERROR[25148] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:43:41] ERROR[25148] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:43:41] ERROR[25148] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:43:41] ERROR[25469] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:43:41] ERROR[25469] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:47:07] ERROR[26214] config_options.c: Unable to load config file ‘acl.conf’
[2019-03-27 10:47:08] ERROR[26216] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:47:08] ERROR[26214] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:47:08] ERROR[26214] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:48:13] ERROR[26666] config_options.c: Unable to load config file ‘acl.conf’
[2019-03-27 10:48:13] ERROR[26668] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:48:13] ERROR[26668] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:48:13] ERROR[26668] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:48:13] ERROR[26666] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:48:13] ERROR[26666] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:50:44] ERROR[27256] config_options.c: Unable to load config file ‘acl.conf’
[2019-03-27 10:50:44] ERROR[27256] res_sorcery_config.c: Unable to load config file ‘pjproject.conf’
[2019-03-27 10:50:44] ERROR[27259] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:50:44] ERROR[27259] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:50:44] ERROR[27259] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:50:44] ERROR[27259] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:50:44] ERROR[27259] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:50:44] ERROR[27256] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:50:44] ERROR[27256] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:51:16] ERROR[27648] config_options.c: Unable to load config file ‘acl.conf’
[2019-03-27 10:51:16] ERROR[27648] res_sorcery_config.c: Unable to load config file ‘pjproject.conf’
[2019-03-27 10:51:16] ERROR[27259] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:51:16] ERROR[27259] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:51:16] ERROR[27259] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:51:16] ERROR[27648] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:51:16] ERROR[27648] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:51:42] ERROR[27955] config_options.c: Unable to load config file ‘acl.conf’
[2019-03-27 10:51:42] ERROR[27259] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:51:42] ERROR[27259] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:51:42] ERROR[27259] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:51:42] ERROR[27259] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:51:42] ERROR[27955] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:51:42] ERROR[27955] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:54:14] ERROR[28538] config_options.c: Unable to load config file ‘acl.conf’
[2019-03-27 10:54:14] ERROR[28542] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:54:14] ERROR[28538] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:54:14] ERROR[28538] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:55:00] ERROR[28883] config_options.c: Unable to load config file ‘acl.conf’
[2019-03-27 10:55:00] ERROR[28883] res_sorcery_config.c: Unable to load config file ‘pjproject.conf’
[2019-03-27 10:55:00] ERROR[28542] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:55:00] ERROR[28542] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:55:00] ERROR[28542] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:55:00] ERROR[28542] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:55:00] ERROR[28542] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:55:00] ERROR[28883] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:55:00] ERROR[28883] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:55:33] ERROR[29244] config_options.c: Unable to load config file ‘acl.conf’
[2019-03-27 10:55:33] ERROR[28542] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:55:33] ERROR[28542] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:55:33] ERROR[28542] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:55:33] ERROR[28542] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:55:33] ERROR[28542] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:55:33] ERROR[29244] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 10:55:33] ERROR[29244] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 11:02:18] ERROR[30490] config_options.c: Unable to load config file ‘acl.conf’
[2019-03-27 11:02:19] ERROR[30490] res_sorcery_config.c: Unable to load config file ‘pjproject.conf’
[2019-03-27 11:02:19] ERROR[30496] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 11:02:19] ERROR[30496] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 11:02:19] ERROR[30496] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 11:02:19] ERROR[30496] res_pjsip_config_wizard.c: Unable to load config file ‘pjsip_wizard.conf’
[2019-03-27 11:20:26] ERROR[2065] config_options.c: Unable to load config file ‘acl.conf’
[2019-03-27 11:20:27] ERROR[2065] config_options.c: Unable to load config file ‘statsd.conf’
[2019-03-27 11:20:27] ERROR[2065] res_sorcery_config.c: Unable to load config file ‘codecs.conf’
[2019-03-27 11:20:27] ERROR[2065] config_options.c: Unable to load config file ‘hep.conf’
[2019-03-27 11:20:27] ERROR[2065] res_calendar.c: Unable to load config calendar.conf
[2019-03-27 11:20:27] ERROR[2065] pbx_lua.c: Error loading extensions.lua: cannot open ‘/etc/asterisk/extensions.lua’ for reading: No such file or directory
[2019-03-27 11:20:27] ERROR[2065] res_config_sqlite.c: Unable to load res_config_sqlite.conf
[2019-03-27 11:20:27] ERROR[2065] chan_dahdi.c: Unable to load config chan_dahdi.conf
[2019-03-27 11:20:28] ERROR[2065] chan_mobile.c: No Bluetooth devices found. Not loading module.
[2019-03-27 11:20:28] ERROR[2065] chan_ooh323.c: Can’t load ooh323 config file, OOH323 Disabled
[2019-03-27 11:20:28] ERROR[2065] config_options.c: Unable to load config file ‘agents.conf’
[2019-03-27 11:20:28] ERROR[2065] app_agent_pool.c: Unable to load config. Not loading module.
[2019-03-27 11:20:28] ERROR[2065] cdr_syslog.c: Unable to load cdr_syslog.conf. Not logging custom CSV CDRs to syslog.
[2019-03-27 11:20:28] ERROR[2065] app_amd.c: Configuration file amd.conf missing.
[2019-03-27 11:20:28] ERROR[2065] chan_phone.c: Unable to load config phone.conf
[2019-03-27 11:20:28] ERROR[2065] chan_unistim.c: Unable to load config unistim.conf
[2019-03-27 11:20:28] ERROR[2065] pbx_dundi.c: Unable to load config dundi.conf
[2019-03-27 11:22:20] ERROR[3676] config_options.c: Unable to load config file ‘acl.conf’
[2019-03-27 11:32:29] ERROR[5175] config_options.c: Unable to load config file ‘acl.conf’
[2019-03-27 13:19:22] ERROR[16471] config_options.c: Unable to load config file ‘acl.conf’
[2019-03-27 13:19:58] ERROR[16906] config_options.c: Unable to load config file ‘acl.conf’
[2019-03-27 13:26:50] ERROR[18071] config_options.c: Unable to load config file ‘acl.conf’
[2019-03-27 13:38:27] ERROR[20337] config_options.c: Unable to load config file ‘acl.conf’
[2019-03-27 13:40:02] ERROR[22004] config_options.c: Unable to load config file ‘acl.conf’
[2019-03-27 13:41:55] ERROR[23685] config_options.c: Unable to load config file ‘acl.conf’
[2019-03-27 13:42:27] ERROR[24217] config_options.c: Unable to load config file ‘acl.conf’
[2019-03-27 13:44:05] ERROR[24870] config_options.c: Unable to load config file ‘acl.conf’
[2019-03-27 13:45:45] ERROR[25442] config_options.c: Unable to load config file ‘acl.conf’
[2019-03-27 13:46:14] ERROR[25887] config_options.c: Unable to load config file ‘acl.conf’

Thanks in advance. I probably haven’t given you what you need here but will do my best!

Michael

jacksm · March 27, 2019, 5:16pm

2 things to add…

When I said outgoing calls were always ok - that may not be true. I was simply making outgoing calls through a softphone connected to Voipfone, rather than through the freePBX, trunk and outbound route.

Secondly, this is also a Google Wifi home environment. I’m still thinking this is all network related so the Google Wifi / NAT is probably a further complication.

Regards
Michael

ambiorixg12 · March 27, 2019, 7:44pm

Your logs doesnt show such message, so this could be posible issue on changes not been applied by the GUI

jacksm · March 27, 2019, 8:27pm

well like I said, if I don’t hit “Apply Config” then it NEVER works. I’m hitting “Apply Config” constantly, plus restarting the server in order to get a connection (albeit brief).

The reason the voicemail prompt doesn’t appear in the logs is because at that point, Asterisk is no longer communicating with the SIP provider (Voipfone).

Could it be an issue with the fragmented packets not being handled by the router (it’s a domestic router after all). I’ve read this could be a possilble cause for communications grinding to a halt shortly after startup.

I hope you can provide some insight cos I’m flying blind at the moment.

Michael

ambiorixg12 · March 27, 2019, 8:34pm

This part it is issue on the GUI, that it is not supported on this forum, related to the connection issue it is a configuration outside Asterisk, that you need to fix it first in order we be able to help with the inbound calls issue, because if there is not connection between Asterisk and the provider it is imposible to debug the problem on the Asterisk side

jacksm · March 27, 2019, 9:21pm

Hi,

Thanks for your prompt replies.

We are not communicating well so sorry for my part in that… I don’t know what part of the issue is “on the GUI”. I can replicate this without any GUI at all by simply editing the files and restarting the server. I’m not aware of any issue with the GUI I’ve indicated.

Secondly, there is no problem communicating between the Asterisk server and the external voip sip. The connection is made, the call is passed to the correct destination (as specified in the extensions_custom.conf file. For that to happen then surely that means communication is happening. The problem is that after around 20 seconds, it APPEARS that the Voip on the SIP goes silent. Nothing is received by Asterisk server (according to the logs).

I was offering as a possible reason the fact that I BELIEVE there is something about these voice communications which means they are characterised as “fragmented packets” and that some hardware fails to cope with fragmented packets.

I’m happy for you to disregard my thoughts but I really do need some pointers here. Pointing me to the GUI or to a general network comms issue doesn’t help as neither of these has been shown.

jacksm · March 27, 2019, 10:05pm

I have carried out a further test, basically switching away from the whole Google Wifi, home router situation and connecting up on a mobile hotspot.

Exactly the same occurred. First inbound call following the asterisk restart was routed correctly. Any subsequent calls went to voicemail.

I’m willing to be told differently but this indicates to me a problem with the Asterisk configuration. I have no idea what… but like I said the same thing has happened now on 3 virtual instances and on 2 different networks.

jacksm · March 28, 2019, 1:40pm

As a further test, I’ve carried out a clean install. Setup one trunk to CHAN_SIP. Then one redirect (for all inbound DIDs) to a “miscellaneous” external number.

If I reboot (or Apply Config) and make one inbound call, it is correctly routed to the external number (the number rings). Once I try again, Asterisk / freepbx doesn’t pick up the inbound and it simply goes to a Voip voicemail…

My question remains… what is stopping Asterisk from picking up the inbound call? It manages it once in the first few seconds of starting but after that - never.

jacksm · March 29, 2019, 2:18am

I’m still spending hours on this.

I’ve been looking at the output from sngrep.

There are REGISTRATION messages and OPTION messages going OUT from PBX… but there are no ACKNOWLEDGEMENTS coming back - nothing shown in sngrep anyway.

I’m guessing this could cause the symptom I’m seeing i.e. following a restart (or Apply Config) everything works perfectly until Asterisk realises it’s messages are not being acknowledged and then it ceases communication… I’m also guessing that takes ABOUT 20 seconds to happen so I have a working instance for about 20 seconds.

If the above IS feasible… how about the reason being that the message header is not being sent back correctly. Maybe it’s using the external IP address? But the messages were sent FROM the internal IP address. No match on IP addresses so the messages aren’t handed back correctly?

The above is a long shot but it’s the best theory I have at the moment.

I could really do with some help here!

Michael

david551 · March 29, 2019, 10:00am

You obviously have to get the NAT configuration correct. If you don’t tell Asterisk your external address it is going to have real difficulties with peers outside the local network.

jacksm · March 31, 2019, 11:08pm

I really felt I’d exhausted all I could on this call.

I thought I’d simplify the problem by doing a clean install and a “hello world” type test.

This has gone badly (getting 403 forbidden in the sip).

Gonna pursue new call Clean install, SIP connections 403 forbidden

May need to come back to this one depending on the learning from the other.

Thanks
Michael

Topic		Replies	Views
I am having problems with out going calls Asterisk Support	12	517	November 15, 2012
[RESOLVED] Trixbox inbound calls not received Asterisk Support	7	291	October 3, 2006
Hi problem with incoming calls from trunk! Asterisk General	1	190	November 2, 2007
Incoming call issue Asterisk Support	2	182	March 24, 2012
HELP: Outbound call to China not working Asterisk Support	1	200	May 7, 2014

freePBX trunk to inbound route works - for about 20 seconds only

Related topics