Has anyone seen this VPN issue?

I have been running an Asterisk setup for the last five or so years and it has worked flawlessly. I have been thrilled with it’s performance.

Here is the setup:
[ul]Centos 5.2[/ul]
[ul]Asterisk 1.4.22[/ul]

As you can see, I haven’t upgraded because it has worked so well for me. However, I tried to make some minor changes recently which cause a problem and I wonder if anyone else has encounter a similar issue?

For the last five years I have run both the Centos server and the phone on the same network without issue. A few days ago I transferred the server onto another network that is connected to the network where the phone is via a working VPN connection. I updated the sip_nat.conf file with the new IP address for the server (I’ve done this before so I know I did this part right). Once it was transferred everything worked except voice from the phone out to the outside. Here’s the details:
[ul]Dial out: working[/ul]
[ul]Dial in: working[/ul]
[ul]Voice from outside to phone: working[/ul]
[ul]Voice from phone to outside: not working[/ul]

The VPN is OpenVPN and I can’t see that it’s blocking any ports. I assume that Asterisk is using a UDP port in the 10000 to 20000 range to send voice out. Has anyone encountered a similar problem or does anyone have any suggestions?

It looks like no one else has experienced this problem?

Can someone point me in the right direction so I can try and trouble-shoot it myself by telling me which port is used to take voice from the phone back to the server?

Thanks in advance for any help

Each side of the conversation selects its incoming ports. For RTP flowing towards Asterisk, the destination port number range is set in rtp.conf (or defaults to 5000 to 31000). The remote device selects the port for RTP flowing away from Asterisk.

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.

That’s a complex dialplan. You need to consult the person who wrote it if you have problems with it. In particular, we don’t support FreePBX here.

However, the issue here probably isn’t with the dialplan. You will need to provide SIP traces containing the SDP exchange, and the sip.conf settings (note FreePBX puts some of these in users.conf).

On the Asterisk CLI run this command rtp set debug on

Check where the RTP traffic is sent. You will see network address and port.

Then make sure the traffic is sent to the correct address and the ports in used are open.