Problems with SIP calls dropping outside of local network

cswnetex · March 29, 2018, 4:36pm

Hello Everyone,

I have an issue with my current configuration running Asterisk 14 and the latest freepbx.

My phone server has two interfaces, one for the local network and one with an external ip address for outside phones.

Everything works fine internally, however extensions that are outside of our local network are dropping outgoing calls after 30 seconds. Incoming calls to the external extensions are fine and do not disconnect.

I cant seem to find anything wrong in the logs that I can myself identify. Can anyone provide any insight?

Any help is appreciated! Thanks a bunch,

Chris W.

[2018-03-29 11:26:27] VERBOSE[16348] netsock2.c: Using SIP RTP Audio TOS bits 184
[2018-03-29 11:26:27] VERBOSE[16348] netsock2.c: Using SIP RTP Audio TOS bits 184 in TCLASS field.
[2018-03-29 11:26:27] VERBOSE[16348] netsock2.c: Using SIP RTP Audio CoS mark 5
[2018-03-29 11:26:27] VERBOSE[31895][C-0000000b] pbx.c: Executing [*97@from-internal:1] Macro("PJSIP/606-00000009", "user-callerid,") in new stack
[2018-03-29 11:26:27] VERBOSE[31895][C-0000000b] pbx.c: Executing [s@macro-user-callerid:1] Set("PJSIP/606-00000009", "TOUCH_MONITOR=1522340787.16") in new stack
[2018-03-29 11:26:27] VERBOSE[31895][C-0000000b] pbx.c: Executing [s@macro-user-callerid:2] Set("PJSIP/606-00000009", "AMPUSER=606") in new stack
[2018-03-29 11:26:27] VERBOSE[31895][C-0000000b] pbx.c: Executing [s@macro-user-callerid:3] GotoIf("PJSIP/606-00000009", "0?report") in new stack
[2018-03-29 11:26:27] VERBOSE[31895][C-0000000b] pbx.c: Executing [s@macro-user-callerid:4] ExecIf("PJSIP/606-00000009", "1?Set(REALCALLERIDNUM=606)") in new stack
[2018-03-29 11:26:27] VERBOSE[31895][C-0000000b] pbx.c: Executing [s@macro-user-callerid:5] Set("PJSIP/606-00000009", "AMPUSER=606") in new stack
[2018-03-29 11:26:27] VERBOSE[31895][C-0000000b] pbx.c: Executing [s@macro-user-callerid:6] GotoIf("PJSIP/606-00000009", "0?limit") in new stack
[2018-03-29 11:26:27] VERBOSE[31895][C-0000000b] pbx.c: Executing [s@macro-user-callerid:7] Set("PJSIP/606-00000009", "AMPUSERCIDNAME=Chris Cell") in new stack
[2018-03-29 11:26:27] VERBOSE[31895][C-0000000b] pbx.c: Executing [s@macro-user-callerid:8] ExecIf("PJSIP/606-00000009", "0?Set(__CIDMASQUERADING=TRUE)") in new stack
[2018-03-29 11:26:27] VERBOSE[31895][C-0000000b] pbx.c: Executing [s@macro-user-callerid:9] GotoIf("PJSIP/606-00000009", "0?report") in new stack
[2018-03-29 11:26:27] VERBOSE[31895][C-0000000b] pbx.c: Executing [s@macro-user-callerid:10] Set("PJSIP/606-00000009", "AMPUSERCID=606") in new stack
[2018-03-29 11:26:27] VERBOSE[31895][C-0000000b] pbx.c: Executing [s@macro-user-callerid:11] Set("PJSIP/606-00000009", "__DIAL_OPTIONS=HhTtr") in new stack
[2018-03-29 11:26:27] VERBOSE[31895][C-0000000b] pbx.c: Executing [s@macro-user-callerid:12] Set("PJSIP/606-00000009", "CALLERID(all)="Chris Cell" <606>") in new stack
[2018-03-29 11:26:27] VERBOSE[31895][C-0000000b] pbx.c: Executing [s@macro-user-callerid:13] GotoIf("PJSIP/606-00000009", "0?limit") in new stack
[2018-03-29 11:26:27] VERBOSE[31895][C-0000000b] pbx.c: Executing [s@macro-user-callerid:14] ExecIf("PJSIP/606-00000009", "0?Set(GROUP(concurrency_limit)=606)") in new stack
[2018-03-29 11:26:27] VERBOSE[31895][C-0000000b] pbx.c: Executing [s@macro-user-callerid:15] NoOp("PJSIP/606-00000009", "Macro Depth is 1") in new stack
[2018-03-29 11:26:27] VERBOSE[31895][C-0000000b] pbx.c: Executing [s@macro-user-callerid:16] GotoIf("PJSIP/606-00000009", "1?report2:macroerror") in new stack
[2018-03-29 11:26:27] VERBOSE[31895][C-0000000b] pbx_builtins.c: Goto (macro-user-callerid,s,17)
[2018-03-29 11:26:27] VERBOSE[31895][C-0000000b] pbx.c: Executing [s@macro-user-callerid:17] GotoIf("PJSIP/606-00000009", "0?continue") in new stack
[2018-03-29 11:26:27] VERBOSE[31895][C-0000000b] pbx.c: Executing [s@macro-user-callerid:18] Set("PJSIP/606-00000009", "__TTL=64") in new stack
[2018-03-29 11:26:27] VERBOSE[31895][C-0000000b] pbx.c: Executing [s@macro-user-callerid:19] GotoIf("PJSIP/606-00000009", "1?continue") in new stack
[2018-03-29 11:26:27] VERBOSE[31895][C-0000000b] pbx_builtins.c: Goto (macro-user-callerid,s,35)
[2018-03-29 11:26:27] VERBOSE[31895][C-0000000b] pbx.c: Executing [s@macro-user-callerid:35] Set("PJSIP/606-00000009", "CALLERID(number)=606") in new stack
[2018-03-29 11:26:27] VERBOSE[31895][C-0000000b] pbx.c: Executing [s@macro-user-callerid:36] Set("PJSIP/606-00000009", "CALLERID(name)=Chris Cell") in new stack
[2018-03-29 11:26:27] VERBOSE[31895][C-0000000b] pbx.c: Executing [s@macro-user-callerid:37] GotoIf("PJSIP/606-00000009", "0?cnum") in new stack
[2018-03-29 11:26:27] VERBOSE[31895][C-0000000b] pbx.c: Executing [s@macro-user-callerid:38] Set("PJSIP/606-00000009", "CDR(cnam)=Chris Cell") in new stack
[2018-03-29 11:26:27] VERBOSE[31895][C-0000000b] pbx.c: Executing [s@macro-user-callerid:39] Set("PJSIP/606-00000009", "CDR(cnum)=606") in new stack
[2018-03-29 11:26:27] VERBOSE[31895][C-0000000b] pbx.c: Executing [s@macro-user-callerid:40] Set("PJSIP/606-00000009", "CHANNEL(language)=en") in new stack
[2018-03-29 11:26:27] VERBOSE[31895][C-0000000b] pbx.c: Executing [*97@from-internal:2] Set("PJSIP/606-00000009", "CONNECTEDLINE(name-charset,i)=utf8") in new stack
[2018-03-29 11:26:27] VERBOSE[31895][C-0000000b] pbx.c: Executing [*97@from-internal:3] Set("PJSIP/606-00000009", "CONNECTEDLINE(name,i)=My Voicemail") in new stack
[2018-03-29 11:26:27] VERBOSE[31895][C-0000000b] pbx.c: Executing [*97@from-internal:4] Set("PJSIP/606-00000009", "CONNECTEDLINE(num,i)=606") in new stack
[2018-03-29 11:26:27] VERBOSE[31895][C-0000000b] pbx.c: Executing [*97@from-internal:5] Answer("PJSIP/606-00000009", "") in new stack
[2018-03-29 11:26:27] VERBOSE[31895][C-0000000b] pbx.c: Executing [*97@from-internal:6] Wait("PJSIP/606-00000009", "1") in new stack
[2018-03-29 11:26:28] VERBOSE[31895][C-0000000b] pbx.c: Executing [*97@from-internal:7] Macro("PJSIP/606-00000009", "get-vmcontext,606") in new stack
[2018-03-29 11:26:28] VERBOSE[31895][C-0000000b] pbx.c: Executing [s@macro-get-vmcontext:1] Set("PJSIP/606-00000009", "VMCONTEXT=default") in new stack
[2018-03-29 11:26:28] VERBOSE[31895][C-0000000b] pbx.c: Executing [s@macro-get-vmcontext:2] GotoIf("PJSIP/606-00000009", "0?200:300") in new stack
[2018-03-29 11:26:28] VERBOSE[31895][C-0000000b] pbx_builtins.c: Goto (macro-get-vmcontext,s,300)
[2018-03-29 11:26:28] VERBOSE[31895][C-0000000b] pbx.c: Executing [s@macro-get-vmcontext:300] NoOp("PJSIP/606-00000009", "") in new stack
[2018-03-29 11:26:28] VERBOSE[31895][C-0000000b] pbx.c: Executing [*97@from-internal:8] Set("PJSIP/606-00000009", "VMBOXEXISTSSTATUS=SUCCESS") in new stack
[2018-03-29 11:26:28] VERBOSE[31895][C-0000000b] pbx.c: Executing [*97@from-internal:9] GotoIf("PJSIP/606-00000009", "1?mbexist") in new stack
[2018-03-29 11:26:28] VERBOSE[31895][C-0000000b] pbx_builtins.c: Goto (from-internal,*97,109)
[2018-03-29 11:26:28] VERBOSE[31895][C-0000000b] pbx.c: Executing [*97@from-internal:109] GotoIf("PJSIP/606-00000009", "1?novmpw:vmpw") in new stack
[2018-03-29 11:26:28] VERBOSE[31895][C-0000000b] pbx_builtins.c: Goto (from-internal,*97,110)
[2018-03-29 11:26:28] VERBOSE[31895][C-0000000b] pbx.c: Executing [*97@from-internal:110] NoOp("PJSIP/606-00000009", "Verifying channel PJSIP/606-00000009 is actually 606") in new stack
[2018-03-29 11:26:28] VERBOSE[31895][C-0000000b] pbx.c: Executing [*97@from-internal:111] Set("PJSIP/606-00000009", "DEVICES=606") in new stack
[2018-03-29 11:26:28] VERBOSE[31895][C-0000000b] pbx.c: Executing [*97@from-internal:112] ExecIf("PJSIP/606-00000009", "0?Set(DEVICES=606)") in new stack
[2018-03-29 11:26:28] VERBOSE[31895][C-0000000b] pbx.c: Executing [*97@from-internal:113] ExecIf("PJSIP/606-00000009", "0?Set(DEVICES=06)") in new stack
[2018-03-29 11:26:28] VERBOSE[31895][C-0000000b] pbx.c: Executing [*97@from-internal:114] While("PJSIP/606-00000009", "1") in new stack
[2018-03-29 11:26:28] VERBOSE[31895][C-0000000b] pbx.c: Executing [*97@from-internal:115] GotoIf("PJSIP/606-00000009", "1?vmpwskip") in new stack
[2018-03-29 11:26:28] VERBOSE[31895][C-0000000b] pbx_builtins.c: Goto (from-internal,*97,120)
[2018-03-29 11:26:28] VERBOSE[31895][C-0000000b] pbx.c: Executing [*97@from-internal:120] VoiceMailMain("PJSIP/606-00000009", "606@default,s") in new stack
[2018-03-29 11:26:28] VERBOSE[31895][C-0000000b] file.c: <PJSIP/606-00000009> Playing 'vm-youhave.ulaw' (language 'en')
[2018-03-29 11:26:29] VERBOSE[31895][C-0000000b] file.c: <PJSIP/606-00000009> Playing 'vm-no.ulaw' (language 'en')
[2018-03-29 11:26:30] VERBOSE[31895][C-0000000b] file.c: <PJSIP/606-00000009> Playing 'vm-messages.ulaw' (language 'en')
[2018-03-29 11:26:31] VERBOSE[31895][C-0000000b] file.c: <PJSIP/606-00000009> Playing 'vm-opts.ulaw' (language 'en')
[2018-03-29 11:26:35] VERBOSE[31895][C-0000000b] file.c: <PJSIP/606-00000009> Playing 'vm-options.ulaw' (language 'en')
[2018-03-29 11:26:54] VERBOSE[31895][C-0000000b] file.c: <PJSIP/606-00000009> Playing 'vm-opts.ulaw' (language 'en')
[2018-03-29 11:26:59] VERBOSE[31895][C-0000000b] pbx.c: Spawn extension (from-internal, *97, 120) exited non-zero on 'PJSIP/606-00000009'
[2018-03-29 11:26:59] VERBOSE[31895][C-0000000b] pbx.c: Executing [h@from-internal:1] Macro("PJSIP/606-00000009", "hangupcall") in new stack
[2018-03-29 11:26:59] VERBOSE[31895][C-0000000b] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("PJSIP/606-00000009", "1?theend") in new stack
[2018-03-29 11:26:59] VERBOSE[31895][C-0000000b] pbx_builtins.c: Goto (macro-hangupcall,s,3)
[2018-03-29 11:26:59] VERBOSE[31895][C-0000000b] pbx.c: Executing [s@macro-hangupcall:3] ExecIf("PJSIP/606-00000009", "0?Set(CDR(recordingfile)=)") in new stack
[2018-03-29 11:26:59] VERBOSE[31895][C-0000000b] pbx.c: Executing [s@macro-hangupcall:4] NoOp("PJSIP/606-00000009", " monior file= ") in new stack
[2018-03-29 11:26:59] VERBOSE[31895][C-0000000b] pbx.c: Executing [s@macro-hangupcall:5] AGI("PJSIP/606-00000009", "attendedtransfer-rec-restart.php,,") in new stack
[2018-03-29 11:26:59] VERBOSE[31895][C-0000000b] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/attendedtransfer-rec-restart.php
[2018-03-29 11:26:59] VERBOSE[31895][C-0000000b] res_agi.c: <PJSIP/606-00000009>AGI Script attendedtransfer-rec-restart.php completed, returning 0
[2018-03-29 11:26:59] VERBOSE[31895][C-0000000b] pbx.c: Executing [s@macro-hangupcall:6] Hangup("PJSIP/606-00000009", "") in new stack
[2018-03-29 11:26:59] VERBOSE[31895][C-0000000b] app_macro.c: Spawn extension (macro-hangupcall, s, 6) exited non-zero on 'PJSIP/606-00000009' in macro 'hangupcall'
[2018-03-29 11:26:59] VERBOSE[31895][C-0000000b] pbx.c: Spawn extension (from-internal, h, 1) exited non-zero on 'PJSIP/606-00000009'``
`

Stewart1 · March 29, 2018, 5:29pm

Dropping after 30 seconds is usually caused by the PBX not receiving an ACK to the 200 OK sent to the extension. From the Asterisk CLI, do
pjsip set logger on
This will add the SIP requests and responses to the log. Make a failing call and look at whether the 200 OK has the correct address (your public IP) and port (5060 or whatever you set ‘port to listen on’ to) in the Contact header.

If the Contact header is wrong, check your settings for External Address and Local Networks. If correct, this is likely a router or firewall issue.

Phone make/model? NAT-related settings on phone? Is LAN subnet at external location same as at the PBX? Router / firewall at remote and local locations? Using UDP, TCP or TLS transport?

cswnetex · March 29, 2018, 9:40pm

Hello, I am using Polycom IP650’s and Zoiper on android cell phones. Both exhibit the same problems.

The outside IP address that is serving the sip clients is not behind a firewall of any sort.

This is what I am seeing exactly at 30 seconds:

I will double check my sip settings.

Best Regards,

Chris W.

SIP/2.0 200 OK
Via: SIP/2.0/UDP 166.137.106.245:14766;rport=14766;received=166.137.106.245;branch=z9hG4bK-524287-1---5cfb658c276972c1
Call-ID: 2xWxUY0qBizaBIvnZj1Rcw..
From: <sip:[email protected]>;tag=67a1d328
To: <sip:*[email protected]>;tag=b02d50f8-3c56-4e9e-8a10-e686546fc62c
CSeq: 2 INVITE
Server: FPBX-14.0.2.12(14.7.6)
Contact: <sip:192.168.1.2:5060>
Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, REFER, MESSAGE
Supported: 100rel, timer, replaces, norefersub
P-Asserted-Identity: "My Voicemail" <sip:[email protected]>
Content-Type: application/sdp
Content-Length:   272

v=0
o=- 0 2 IN IP4 206.123.142.121
s=Asterisk
c=IN IP4 206.123.142.121
t=0 0
m=audio 10620 RTP/AVP 0 8 3 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

[2018-03-29 16:39:08] VERBOSE[1289] res_pjsip_logger.c: <--- Transmitting SIP request (392 bytes) to UDP:166.137.106.245:14766 --->
BYE sip:[email protected]:14766 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.2:5060;rport;branch=z9hG4bKPjc305a608-76c3-4104-8fa5-b3f874cb4f84
From: <sip:*[email protected]>;tag=b02d50f8-3c56-4e9e-8a10-e686546fc62c
To: <sip:[email protected]>;tag=67a1d328
Call-ID: 2xWxUY0qBizaBIvnZj1Rcw..
CSeq: 8355 BYE
Max-Forwards: 70
User-Agent: FPBX-14.0.2.12(14.7.6)
Content-Length:  0

[2018-03-29 16:39:09] VERBOSE[1289] res_pjsip_logger.c: <--- Received SIP response (429 bytes) from UDP:166.137.106.245:14766 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.2:5060;rport=5060;branch=z9hG4bKPjc305a608-76c3-4104-8fa5-b3f874cb4f84;received=206.123.142.121
Contact: <sip:[email protected]:14766;transport=UDP>
To: <sip:[email protected]>;tag=67a1d328
From: <sip:*[email protected]>;tag=b02d50f8-3c56-4e9e-8a10-e686546fc62c
Call-ID: 2xWxUY0qBizaBIvnZj1Rcw..
CSeq: 8355 BYE
User-Agent: Zoiper rv2.8.87-mod
Content-Length: 0

Stewart1 · March 30, 2018, 1:57am

I’m very puzzled. Indeed, the problem is that the Contact header has 192.168.1.2 (which I assume is the LAN address of your PBX), but it obviously knows its WAN IP because 206.123.142.121 appears correctly in the SDP of the same packet.

Take a look at your /etc/asterisk/pjsip.transports.conf file. I don’t have a setup with two interfaces, but would expect to see a section for your WAN interface that contains:
external_media_address=206.123.142.121
external_signaling_address=206.123.142.121

If you don’t see that, try going to Asterisk SIP Settings ->Chan PJSIP Settings, setting External IP Address for the appropriate interface, then restarting (not just reloading) Asterisk.

If no luck, a chan_sip extension may be a workaround, or overriding the config with pjsip.transports_custom.conf , but I don’t understand what is happening. Possibly someone with a box with two NICs can chime in here.

cswnetex · March 30, 2018, 3:53am

I double checked both,

pjsip.transports.conf:external_media_address=206.123.142.121
pjsip.transports.conf:external_signaling_address=206.123.142.121

It’s for sure strange, as I mentioned incoming calls to remote phones are working great, it’s just outbound calls.

I will give it a shot with chan_sip and see what happens.

Best Regards & thanks for the help,

Chris W.

Stewart1 · March 30, 2018, 6:28am

That’s not surprising for this issue. On an inbound call, the extension is sending the 200 and the PBX is sending the ACK. Asterisk is smart enough to send the ACK back to the address/port the 200 came from, if the Contact header looks like a NAT address.

A couple of other thoughts:

In the Transports section of PJSIP Settings, you may need to disable the “udp - 0.0.0.0 - All” entry and enable a separate transport for each interface. Then (after saving) at the bottom of the page you’ll see separate sections for each transport.

I found a thread discussing a similar issue, showing how to do some manual tweaking: Custom transport in PJSIP, possible from GUI? - #5 by lgaetz . However, if that’s necessary, chan_sip is probably simpler (if it in fact works).

cswnetex · March 30, 2018, 8:03am

I switched to chan_sip and now everything is working fine.

I’m still going to dig into what exactly is going on.

Best Regards,

Chris W.

system · March 30, 2019, 8:04am

This topic was automatically closed 365 days after the last reply. New replies are no longer allowed.