I have been working on this issue for a while now and have made some progress but still have not solved the problem.
I’ve eliminated the VPN as a variable in the problem. I’ve re-created the issue with the phone on the same network as the server (inside the firewall with no VPN connection).
I’ve looked at the “full” log file but everything appears to be ok. Perhaps there’s someone with more knowledge that can see a concern so here’s the full log of a call from start to hangup (any help or direction will be very much appreciated):
[Mar 7 16:06:38] VERBOSE[3271] logger.c: -- Starting simple switch on 'Zap/4-1'
[Mar 7 16:06:42] NOTICE[3271] chan_zap.c: Got event 18 (Ring Begin)...
[Mar 7 16:06:44] NOTICE[3271] chan_zap.c: Got event 2 (Ring/Answered)...
[Mar 7 16:06:44] VERBOSE[3271] logger.c: -- Executing [s@from-zaptel:1] NoOp("Zap/4-1", "Entering from-zaptel with DID == ") in new stack
[Mar 7 16:06:44] VERBOSE[3271] logger.c: -- Executing [s@from-zaptel:2] Ringing("Zap/4-1", "") in new stack
[Mar 7 16:06:44] VERBOSE[3271] logger.c: -- Executing [s@from-zaptel:3] Set("Zap/4-1", "DID=s") in new stack
[Mar 7 16:06:44] VERBOSE[3271] logger.c: -- Executing [s@from-zaptel:4] NoOp("Zap/4-1", "DID is now s") in new stack
[Mar 7 16:06:44] VERBOSE[3271] logger.c: -- Executing [s@from-zaptel:5] GotoIf("Zap/4-1", "1?zapok:notzap") in new stack
[Mar 7 16:06:44] VERBOSE[3271] logger.c: -- Goto (from-zaptel,s,8)
[Mar 7 16:06:44] VERBOSE[3271] logger.c: -- Executing [s@from-zaptel:8] NoOp("Zap/4-1", "Is a Zaptel Channel") in new stack
[Mar 7 16:06:44] VERBOSE[3271] logger.c: -- Executing [s@from-zaptel:9] Set("Zap/4-1", "CHAN=4-1") in new stack
[Mar 7 16:06:44] VERBOSE[3271] logger.c: -- Executing [s@from-zaptel:10] Set("Zap/4-1", "CHAN=4") in new stack
[Mar 7 16:06:44] VERBOSE[3271] logger.c: -- Executing [s@from-zaptel:11] Macro("Zap/4-1", "from-zaptel-4|s|1") in new stack
[Mar 7 16:06:44] WARNING[3271] app_macro.c: No such context 'macro-from-zaptel-4' for macro 'from-zaptel-4'
[Mar 7 16:06:44] VERBOSE[3271] logger.c: -- Executing [s@from-zaptel:12] NoOp("Zap/4-1", "Returned from Macro from-zaptel-4") in new stack
[Mar 7 16:06:44] VERBOSE[3271] logger.c: -- Executing [s@from-zaptel:13] Goto("Zap/4-1", "from-pstn|s|1") in new stack
[Mar 7 16:06:44] VERBOSE[3271] logger.c: -- Goto (from-pstn,s,1)
[Mar 7 16:06:44] VERBOSE[3271] logger.c: -- Executing [s@from-pstn:1] Set("Zap/4-1", "__FROM_DID=s") in new stack
[Mar 7 16:06:44] VERBOSE[3271] logger.c: -- Executing [s@from-pstn:2] Gosub("Zap/4-1", "app-blacklist-check|s|1") in new stack
[Mar 7 16:06:44] VERBOSE[3271] logger.c: -- Executing [s@app-blacklist-check:1] LookupBlacklist("Zap/4-1", "") in new stack
[Mar 7 16:06:44] WARNING[3271] app_lookupblacklist.c: LookupBlacklist is deprecated. Please use ${BLACKLIST()} instead.
[Mar 7 16:06:44] VERBOSE[3271] logger.c: -- Executing [s@app-blacklist-check:2] GotoIf("Zap/4-1", "0?blacklisted") in new stack
[Mar 7 16:06:44] VERBOSE[3271] logger.c: -- Executing [s@app-blacklist-check:3] Return("Zap/4-1", "") in new stack
[Mar 7 16:06:44] VERBOSE[3271] logger.c: -- Executing [s@from-pstn:3] ExecIf("Zap/4-1", "1 |Set|CALLERID(name)=") in new stack
[Mar 7 16:06:44] VERBOSE[3271] logger.c: -- Executing [s@from-pstn:4] Set("Zap/4-1", "FAX_RX=disabled") in new stack
[Mar 7 16:06:44] VERBOSE[3271] logger.c: -- Executing [s@from-pstn:5] Set("Zap/4-1", "__CALLINGPRES_SV=allowed_not_screened") in new stack
[Mar 7 16:06:44] VERBOSE[3271] logger.c: -- Executing [s@from-pstn:6] SetCallerPres("Zap/4-1", "allowed_not_screened") in new stack
[Mar 7 16:06:44] VERBOSE[3271] logger.c: -- Executing [s@from-pstn:7] Goto("Zap/4-1", "ivr-4|s|1") in new stack
[Mar 7 16:06:44] VERBOSE[3271] logger.c: -- Goto (ivr-4,s,1)
[Mar 7 16:06:44] VERBOSE[3271] logger.c: -- Executing [s@ivr-4:1] Set("Zap/4-1", "MSG=custom/cb-main-greeting") in new stack
[Mar 7 16:06:44] VERBOSE[3271] logger.c: -- Executing [s@ivr-4:2] Set("Zap/4-1", "LOOPCOUNT=0") in new stack
[Mar 7 16:06:44] VERBOSE[3271] logger.c: -- Executing [s@ivr-4:3] Set("Zap/4-1", "__DIR-CONTEXT=default") in new stack
[Mar 7 16:06:44] VERBOSE[3271] logger.c: -- Executing [s@ivr-4:4] Set("Zap/4-1", "_IVR_CONTEXT_ivr-4=") in new stack
[Mar 7 16:06:44] VERBOSE[3271] logger.c: -- Executing [s@ivr-4:5] Set("Zap/4-1", "_IVR_CONTEXT=ivr-4") in new stack
[Mar 7 16:06:44] VERBOSE[3271] logger.c: -- Executing [s@ivr-4:6] GotoIf("Zap/4-1", "0?begin") in new stack
[Mar 7 16:06:44] VERBOSE[3271] logger.c: -- Executing [s@ivr-4:7] Answer("Zap/4-1", "") in new stack
[Mar 7 16:06:44] DEBUG[3271] chan_zap.c: Took Zap/4-1 off hook
[Mar 7 16:06:44] DEBUG[3271] chan_zap.c: No echo training requested
[Mar 7 16:06:44] VERBOSE[3271] logger.c: -- Executing [s@ivr-4:8] Wait("Zap/4-1", "1") in new stack
[Mar 7 16:06:45] VERBOSE[3271] logger.c: -- Executing [s@ivr-4:9] Set("Zap/4-1", "TIMEOUT(digit)=3") in new stack
[Mar 7 16:06:45] VERBOSE[3271] logger.c: -- Digit timeout set to 3
[Mar 7 16:06:45] VERBOSE[3271] logger.c: -- Executing [s@ivr-4:10] Set("Zap/4-1", "TIMEOUT(response)=1") in new stack
[Mar 7 16:06:45] VERBOSE[3271] logger.c: -- Response timeout set to 1
[Mar 7 16:06:45] VERBOSE[3271] logger.c: -- Executing [s@ivr-4:11] Set("Zap/4-1", "__IVR_RETVM=") in new stack
[Mar 7 16:06:45] VERBOSE[3271] logger.c: -- Executing [s@ivr-4:12] ExecIf("Zap/4-1", "1|Background|custom/cb-main-greeting") in new stack
[Mar 7 16:06:45] VERBOSE[3271] logger.c: -- <Zap/4-1> Playing 'custom/cb-main-greeting' (language 'en')
[Mar 7 16:06:49] VERBOSE[3271] logger.c: == CDR updated on Zap/4-1
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- Executing [200@ivr-4:1] DBdel("Zap/4-1", "") in new stack
[Mar 7 16:06:49] WARNING[3271] app_db.c: The DBdel application has been deprecated in favor of the DB_DELETE dialplan function!
[Mar 7 16:06:49] DEBUG[3271] app_db.c: Ignoring, no parameters
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- Executing [200@ivr-4:2] Set("Zap/4-1", "__NODEST=") in new stack
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- Executing [200@ivr-4:3] Goto("Zap/4-1", "from-did-direct|200|1") in new stack
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- Goto (from-did-direct,200,1)
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- Executing [200@from-did-direct:1] Macro("Zap/4-1", "exten-vm|200|200") in new stack
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- Executing [s@macro-exten-vm:1] Macro("Zap/4-1", "user-callerid") in new stack
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- Executing [s@macro-user-callerid:1] Set("Zap/4-1", "AMPUSER=") in new stack
[Mar 7 16:06:49] DEBUG[3271] app_macro.c: Executed application: Set
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- Executing [s@macro-user-callerid:2] GotoIf("Zap/4-1", "0?report") in new stack
[Mar 7 16:06:49] DEBUG[3271] app_macro.c: Executed application: GotoIf
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- Executing [s@macro-user-callerid:3] ExecIf("Zap/4-1", "1|Set|REALCALLERIDNUM=") in new stack
[Mar 7 16:06:49] DEBUG[3271] app_macro.c: Executed application: ExecIf
[Mar 7 16:06:49] DEBUG[3271] app_macro.c: Last app: Set|REALCALLERIDNUM=
[Mar 7 16:06:49] DEBUG[3271] func_db.c: DB: DEVICE//user not found in database.
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- Executing [s@macro-user-callerid:4] Set("Zap/4-1", "AMPUSER=") in new stack
[Mar 7 16:06:49] DEBUG[3271] app_macro.c: Executed application: Set
[Mar 7 16:06:49] DEBUG[3271] func_db.c: DB: AMPUSER//cidname not found in database.
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- Executing [s@macro-user-callerid:5] Set("Zap/4-1", "AMPUSERCIDNAME=") in new stack
[Mar 7 16:06:49] DEBUG[3271] app_macro.c: Executed application: Set
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- Executing [s@macro-user-callerid:6] GotoIf("Zap/4-1", "1?report") in new stack
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- Goto (macro-user-callerid,s,11)
[Mar 7 16:06:49] DEBUG[3271] app_macro.c: Executed application: GotoIf
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- Executing [s@macro-user-callerid:11] GotoIf("Zap/4-1", "0?continue") in new stack
[Mar 7 16:06:49] DEBUG[3271] app_macro.c: Executed application: GotoIf
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- Executing [s@macro-user-callerid:12] Set("Zap/4-1", "__TTL=64") in new stack
[Mar 7 16:06:49] DEBUG[3271] app_macro.c: Executed application: Set
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- Executing [s@macro-user-callerid:13] GotoIf("Zap/4-1", "1?continue") in new stack
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- Goto (macro-user-callerid,s,20)
[Mar 7 16:06:49] DEBUG[3271] app_macro.c: Executed application: GotoIf
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- Executing [s@macro-user-callerid:20] NoOp("Zap/4-1", "Using CallerID "" <>") in new stack
[Mar 7 16:06:49] DEBUG[3271] app_macro.c: Executed application: Noop
[Mar 7 16:06:49] DEBUG[3271] app_macro.c: Executed application: Macro
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- Executing [s@macro-exten-vm:2] Set("Zap/4-1", "RingGroupMethod=none") in new stack
[Mar 7 16:06:49] DEBUG[3271] app_macro.c: Executed application: Set
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- Executing [s@macro-exten-vm:3] Set("Zap/4-1", "VMBOX=200") in new stack
[Mar 7 16:06:49] DEBUG[3271] app_macro.c: Executed application: Set
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- Executing [s@macro-exten-vm:4] Set("Zap/4-1", "EXTTOCALL=200") in new stack
[Mar 7 16:06:49] DEBUG[3271] app_macro.c: Executed application: Set
[Mar 7 16:06:49] DEBUG[3271] func_db.c: DB: CFU/200 not found in database.
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- Executing [s@macro-exten-vm:5] Set("Zap/4-1", "CFUEXT=") in new stack
[Mar 7 16:06:49] DEBUG[3271] app_macro.c: Executed application: Set
[Mar 7 16:06:49] DEBUG[3271] func_db.c: DB: CFB/200 not found in database.
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- Executing [s@macro-exten-vm:6] Set("Zap/4-1", "CFBEXT=") in new stack
[Mar 7 16:06:49] DEBUG[3271] app_macro.c: Executed application: Set
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- Executing [s@macro-exten-vm:7] Set("Zap/4-1", "RT=15") in new stack
[Mar 7 16:06:49] DEBUG[3271] app_macro.c: Executed application: Set
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- Executing [s@macro-exten-vm:8] Macro("Zap/4-1", "record-enable|200|IN") in new stack
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- Executing [s@macro-record-enable:1] GotoIf("Zap/4-1", "1?check") in new stack
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- Goto (macro-record-enable,s,4)
[Mar 7 16:06:49] DEBUG[3271] app_macro.c: Executed application: GotoIf
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- Executing [s@macro-record-enable:4] AGI("Zap/4-1", "recordingcheck|20140307-160649|1394233598.0") in new stack
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
[Mar 7 16:06:49] VERBOSE[3271] logger.c: recordingcheck|20140307-160649|1394233598.0: Inbound recording not enabled
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- AGI Script recordingcheck completed, returning 0
[Mar 7 16:06:49] DEBUG[3271] app_macro.c: Executed application: AGI
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- Executing [s@macro-record-enable:5] MacroExit("Zap/4-1", "") in new stack
[Mar 7 16:06:49] DEBUG[3271] app_macro.c: Executed application: Macro
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- Executing [s@macro-exten-vm:9] Macro("Zap/4-1", "dial|15|tr|200") in new stack
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- Executing [s@macro-dial:1] GotoIf("Zap/4-1", "1?dial") in new stack
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- Goto (macro-dial,s,3)
[Mar 7 16:06:49] DEBUG[3271] app_macro.c: Executed application: GotoIf
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- Executing [s@macro-dial:3] AGI("Zap/4-1", "dialparties.agi") in new stack
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
[Mar 7 16:06:49] VERBOSE[3271] logger.c: dialparties.agi: Starting New Dialparties.agi
[Mar 7 16:06:49] VERBOSE[3275] logger.c: == Parsing '/etc/asterisk/manager.conf': [Mar 7 16:06:49] VERBOSE[3275] logger.c: Found
[Mar 7 16:06:49] VERBOSE[3275] logger.c: == Parsing '/etc/asterisk/manager_additional.conf': [Mar 7 16:06:49] VERBOSE[3275] logger.c: Found
[Mar 7 16:06:49] VERBOSE[3275] logger.c: == Parsing '/etc/asterisk/manager_custom.conf': [Mar 7 16:06:49] VERBOSE[3275] logger.c: Found
[Mar 7 16:06:49] VERBOSE[3275] logger.c: == Manager 'admin' logged on from 127.0.0.1
[Mar 7 16:06:49] VERBOSE[3271] logger.c: dialparties.agi: Caller ID name is 'unknown' number is 'unknown'
[Mar 7 16:06:49] VERBOSE[3271] logger.c: dialparties.agi: Methodology of ring is 'none'
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- dialparties.agi: Added extension 200 to extension map
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- dialparties.agi: Extension 200 cf is disabled
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- dialparties.agi: Extension 200 do not disturb is disabled
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- dialparties.agi: DbDel CALLTRACE/200 - Caller ID is not defined
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- dialparties.agi: Filtered ARG3: 200
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- AGI Script dialparties.agi completed, returning 0
[Mar 7 16:06:49] DEBUG[3271] app_macro.c: Executed application: AGI
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- Executing [s@macro-dial:7] Dial("Zap/4-1", "SIP/200|15|tr") in new stack
[Mar 7 16:06:49] VERBOSE[3271] logger.c: -- Called 200
[Mar 7 16:06:49] VERBOSE[3275] logger.c: == Manager 'admin' logged off from 127.0.0.1
[Mar 7 16:06:50] VERBOSE[3271] logger.c: -- SIP/200-08af80e8 is ringing
[Mar 7 16:06:52] VERBOSE[3271] logger.c: -- SIP/200-08af80e8 answered Zap/4-1
[Mar 7 16:07:09] VERBOSE[3271] logger.c: == Spawn extension (macro-dial, s, 7) exited non-zero on 'Zap/4-1' in macro 'dial'
[Mar 7 16:07:09] VERBOSE[3271] logger.c: == Spawn extension (macro-dial, s, 7) exited non-zero on 'Zap/4-1' in macro 'exten-vm'
[Mar 7 16:07:09] VERBOSE[3271] logger.c: == Spawn extension (macro-dial, s, 7) exited non-zero on 'Zap/4-1'
[Mar 7 16:07:09] VERBOSE[3271] logger.c: -- Executing [h@macro-dial:1] Macro("Zap/4-1", "hangupcall") in new stack
[Mar 7 16:07:09] VERBOSE[3271] logger.c: -- Executing [s@macro-hangupcall:1] ResetCDR("Zap/4-1", "w") in new stack
[Mar 7 16:07:09] DEBUG[3271] app_macro.c: Executed application: ResetCDR
[Mar 7 16:07:09] VERBOSE[3271] logger.c: -- Executing [s@macro-hangupcall:2] NoCDR("Zap/4-1", "") in new stack
[Mar 7 16:07:09] DEBUG[3271] app_macro.c: Executed application: NoCDR
[Mar 7 16:07:09] VERBOSE[3271] logger.c: -- Executing [s@macro-hangupcall:3] GotoIf("Zap/4-1", "1?skiprg") in new stack
[Mar 7 16:07:09] VERBOSE[3271] logger.c: -- Goto (macro-hangupcall,s,6)
[Mar 7 16:07:09] DEBUG[3271] app_macro.c: Executed application: GotoIf
[Mar 7 16:07:09] VERBOSE[3271] logger.c: -- Executing [s@macro-hangupcall:6] GotoIf("Zap/4-1", "1?skipblkvm") in new stack
[Mar 7 16:07:09] VERBOSE[3271] logger.c: -- Goto (macro-hangupcall,s,9)
[Mar 7 16:07:09] DEBUG[3271] app_macro.c: Executed application: GotoIf
[Mar 7 16:07:09] VERBOSE[3271] logger.c: -- Executing [s@macro-hangupcall:9] GotoIf("Zap/4-1", "1?theend") in new stack
[Mar 7 16:07:09] VERBOSE[3271] logger.c: -- Goto (macro-hangupcall,s,11)
[Mar 7 16:07:09] DEBUG[3271] app_macro.c: Executed application: GotoIf
[Mar 7 16:07:09] VERBOSE[3271] logger.c: -- Executing [s@macro-hangupcall:11] Hangup("Zap/4-1", "") in new stack
[Mar 7 16:07:09] VERBOSE[3271] logger.c: == Spawn extension (macro-hangupcall, s, 11) exited non-zero on 'Zap/4-1' in macro 'hangupcall'
[Mar 7 16:07:09] VERBOSE[3271] logger.c: == Spawn extension (macro-hangupcall, s, 11) exited non-zero on 'Zap/4-1'
[Mar 7 16:07:09] VERBOSE[3271] logger.c: -- Hungup 'Zap/4-1'
[Mar 7 16:07:09] WARNING[2723] chan_sip.c: Remote host can't match request BYE to call '533787527e400c4a3b3c1235233561a7@XXX.XXX.XXX.XXX'. Giving up.