Poor voice quality or can't hear remote external user after 30 seconds

General Help
1

I have inherited an existing asterisk (1.6.2.10) system (FreePBX 2.8.1.5) It has been running quite happily for some time but external users are starting to break up after about 30 seconds or they are unable to hear me but I can hear them.

I “think” everything is correct but don’t know enough to guarantee this. Can someone have a quick look at the global settings so that I can at least rule that out and start looking at the routers and switches.

Any help would be greatly appreciated.

Global Settings:

UDP SIP Port: 5060
UDP Bindaddress: 0.0.0.0
TCP SIP Port: Disabled
TLS SIP Port: Disabled
Videosupport: No
Textsupport: No
Ignore SDP sess. ver.: No
AutoCreate Peer: No
Match Auth Username: No
Allow unknown access: No
Allow subscriptions: Yes
Allow overlap dialing: Yes
Allow promsic. redir: No
Enable call counters: No
SIP domain support: No
Realm. auth: No
Our auth realm asterisk
Call to non-local dom.: Yes
URI user is phone no: No
Always auth rejects: Yes
Direct RTP setup: No
User Agent: FPBX-2.8.1(1.6.2.10)
SDP Session Name: Asterisk PBX 1.6.2.10
SDP Owner Name: root
Reg. context: (not set)
Regexten on Qualify: No
Caller ID: Unknown
From: Domain:
Record SIP history: Off
Call Events: Off
Auth. Failure Events: Off
T.38 support: No
T.38 EC mode: Unknown
T.38 MaxDtgrm: -1
SIP realtime: Disabled
Qualify Freq : 60000 ms

Network QoS Settings:

IP ToS SIP: CS3
IP ToS RTP audio: EF
IP ToS RTP video: AF41
IP ToS RTP text: CS0
802.1p CoS SIP: 4
802.1p CoS RTP audio: 5
802.1p CoS RTP video: 6
802.1p CoS RTP text: 5
Jitterbuffer enabled: No
Jitterbuffer forced: No
Jitterbuffer max size: -1
Jitterbuffer resync: -1
Jitterbuffer impl:
Jitterbuffer log: No

Network Settings:

SIP address remapping: Enabled using externip
Externhost:
Externip: x.x.x.x:5060
Externrefresh: 10
Internal IP: 10.8.64.150:5060
Localnet: 10.8.0.0/255.255.0.0
192.168.220.0/255.255.255.0
192.168.210.0/255.255.255.0
192.168.250.0/255.255.255.0
192.168.240.0/255.255.255.0
STUN server: 0.0.0.0:0

Global Signalling Settings:

Codecs: 0x90f (g723|gsm|ulaw|alaw|g726|g729)
Codec Order: ulaw:20,alaw:20,gsm:20,g729:20,g723:30,g726:20
Relax DTMF: No
RFC2833 Compensation: No
Compact SIP headers: No
RTP Keepalive: 0 (Disabled)
RTP Timeout: 30
RTP Hold Timeout: 300
MWI NOTIFY mime type: application/simple-message-summary
DNS SRV lookup: No
Pedantic SIP support: No
Reg. min duration 60 secs
Reg. max duration: 600 secs
Reg. default duration: 120 secs
Outbound reg. timeout: 20 secs
Outbound reg. attempts: 0
Notify ringing state: Yes
Include CID: No
Notify hold state: Yes
SIP Transfer mode: open
Max Call Bitrate: 384 kbps
Auto-Framing: No
Outb. proxy:
Session Timers: Accept
Session Refresher: uas
Session Expires: 1800 secs
Session Min-SE: 90 secs
Timer T1: 500
Timer T1 minimum: 100
Timer B: 32000
No premature media: Yes

Default Settings:

Allowed transports: UDP
Outbound transport: UDP
Context: from-sip-external
Nat: Always
DTMF: rfc2833
Qualify: 0
Use ClientCode: No
Progress inband: Never
Language:
MOH Interpret: default
MOH Suggest:
Voice Mail Extension: *97

2

Thanks bk. Let us know what you find.

3

this will probably point you in a direction pretty quickly - look for “timeout” or “giving up”. i am pretty sure we fought this problem a long time ago and it turned out to be something stupid. i will have to look back into our notes and see if i can find info on this.

4

/var/log/astersik/full - but please don’t post the entire log, just the piece of it that pertains to a call where the voice stopped working

5

Did you ever find a solution? We have a similar issue with a new 2.11 installation. In our case the issue happens after about 2 to 3 minutes, then the other end can’t hear us.

Olly

6

Hi Olly, No I’m afraid that we are still having the same issues and in fact things have taken a downward spiral and all bar one external user is unable to hear or be heard. I do believe that this (for us at least) is a firewall/NAT issue but can’t pin it down.

Have you done any packet capture and if so what was the result?
If you haven’t, I would suggest that you use wireshark to capture traffic on the WAN interface, LAN interface and at the asterisk server. This should at least tell you where the issues start.

Current issues:
This started out as an intermitant fault but is now consistant. All bar one external users are unable to hear the other end of the conversation regardless of who initiates the call.

We have even hired an Asterisk consultant who was able to confirm that there are no issues with the Asterisk config. Packet capture on the WAN interface of the firewall clearly shows both side of the call. I can rebuild the captured call and hear both sides of the clearly.

FYI, We use a pfsense firewall.

7

we’re seeing this on internal calls over the VPN, which is an oddity.

Apparently the time it takes to stop hearing one party varies. Some reports say its instantly and others say it takes several minutes.

We’re running draytek routers at each end with the SIP ALG feature disabled.

I’ve tested outbound calls and it appears to be ok for me. I’m looking at the phones or the vpn as the cause.

Olly

8

Hi

Here’s my log snippet of a call between 103 and 100.

[2013-06-24 11:38:31] VERBOSE[1619] asterisk.c: – Remote UNIX connection
[2013-06-24 11:38:31] VERBOSE[26852] asterisk.c: – Remote UNIX connection disconnected
[2013-06-24 11:41:06] VERBOSE[1749] chan_sip.c: – Registered SIP ‘103’ at 10.1.39.44:5062
[2013-06-24 11:41:10] NOTICE[1749] chan_sip.c: Peer ‘103’ is now UNREACHABLE! Last qualify: 0
[2013-06-24 11:45:14] VERBOSE[1749] netsock2.c: == Using SIP VIDEO TOS bits 136
[2013-06-24 11:45:14] VERBOSE[1749] netsock2.c: == Using SIP VIDEO CoS mark 6
[2013-06-24 11:45:14] VERBOSE[1749] netsock2.c: == Using SIP RTP TOS bits 184
[2013-06-24 11:45:14] VERBOSE[1749] netsock2.c: == Using SIP RTP CoS mark 5
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [100@from-internal:1] Set(“SIP/103-00000095”, “__RINGTIMER=15”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [100@from-internal:2] Macro(“SIP/103-00000095”, “exten-vm,novm,100,0,0,0”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-exten-vm:1] Macro(“SIP/103-00000095”, “user-callerid,”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-user-callerid:1] Set(“SIP/103-00000095”, “TOUCH_MONITOR=1372070714.149”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-user-callerid:2] Set(“SIP/103-00000095”, “AMPUSER=103”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-user-callerid:3] GotoIf(“SIP/103-00000095”, “0?report”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-user-callerid:4] ExecIf(“SIP/103-00000095”, “1?Set(REALCALLERIDNUM=103)”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-user-callerid:5] Set(“SIP/103-00000095”, “AMPUSER=103”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-user-callerid:6] Set(“SIP/103-00000095”, “AMPUSERCIDNAME=Ext 103”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-user-callerid:7] GotoIf(“SIP/103-00000095”, “0?report”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-user-callerid:8] Set(“SIP/103-00000095”, “AMPUSERCID=103”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-user-callerid:9] Set(“SIP/103-00000095”, “__DIAL_OPTIONS=Ttr”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-user-callerid:10] Set(“SIP/103-00000095”, “CALLERID(all)=“Ext 103” <103>”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-user-callerid:11] GotoIf(“SIP/103-00000095”, “0?limit”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-user-callerid:12] ExecIf(“SIP/103-00000095”, “0?Set(GROUP(concurrency_limit)=103)”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-user-callerid:13] GosubIf(“SIP/103-00000095”, “7?sub-ccss,s,1(macro-exten-vm,100)”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@sub-ccss:1] ExecIf(“SIP/103-00000095”, “0?Return()”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@sub-ccss:2] Set(“SIP/103-00000095”, “CCSS_SETUP=TRUE”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@sub-ccss:3] GosubIf(“SIP/103-00000095”, “0?monitor_config,1(macro-exten-vm,100):monitor_default,1(macro-exten-vm,100)”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [monitor_default@sub-ccss:1] GotoIf(“SIP/103-00000095”, “1?is_exten”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Goto (sub-ccss,monitor_default,4)
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [monitor_default@sub-ccss:4] Set(“SIP/103-00000095”, “CALLCOMPLETION(cc_monitor_policy)=generic”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [monitor_default@sub-ccss:5] Set(“SIP/103-00000095”, “CALLCOMPLETION(cc_max_monitors)=5”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [monitor_default@sub-ccss:6] Return(“SIP/103-00000095”, “TRUE”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@sub-ccss:4] GosubIf(“SIP/103-00000095”, “7?agent_config,1():agent_default,1()”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [agent_config@sub-ccss:1] Set(“SIP/103-00000095”, “CALLCOMPLETION(cc_agent_policy)=generic”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [agent_config@sub-ccss:2] Set(“SIP/103-00000095”, “CALLCOMPLETION(cc_offer_timer)=30”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [agent_config@sub-ccss:3] Set(“SIP/103-00000095”, “CALLCOMPLETION(ccbs_available_timer)=”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [agent_config@sub-ccss:4] Set(“SIP/103-00000095”, “CALLCOMPLETION(ccnr_available_timer)=”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [agent_config@sub-ccss:5] Set(“SIP/103-00000095”, “CALLCOMPLETION(cc_callback_macro)=ccss-default”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [agent_config@sub-ccss:6] ExecIf(“SIP/103-00000095”, “1?Set(CALLCOMPLETION(cc_recall_timer)=)”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [agent_config@sub-ccss:7] ExecIf(“SIP/103-00000095”, “1?Set(CALLCOMPLETION(cc_max_agents)=)”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [agent_config@sub-ccss:8] ExecIf(“SIP/103-00000095”, “0?Set(CALLCOMPLETION(cc_agent_dialstring)=Local/103_100@from-ccss-)”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [agent_config@sub-ccss:9] Set(“SIP/103-00000095”, “CALLCOMPLETION(cc_callback_macro)=ccss-default”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [agent_config@sub-ccss:10] Return(“SIP/103-00000095”, “”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@sub-ccss:5] Set(“SIP/103-00000095”, “DB(AMPUSER/103/ccss/last_number)=100”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@sub-ccss:6] Return(“SIP/103-00000095”, “”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-user-callerid:14] ExecIf(“SIP/103-00000095”, “0?Set(CHANNEL(language)=)”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-user-callerid:15] GotoIf(“SIP/103-00000095”, “0?continue”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-user-callerid:16] Set(“SIP/103-00000095”, “__TTL=64”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-user-callerid:17] GotoIf(“SIP/103-00000095”, “1?continue”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Goto (macro-user-callerid,s,28)
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-user-callerid:28] Set(“SIP/103-00000095”, “CALLERID(number)=103”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-user-callerid:29] Set(“SIP/103-00000095”, “CALLERID(name)=Ext 103”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-user-callerid:30] Set(“SIP/103-00000095”, “CDR(cnum)=103”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-user-callerid:31] Set(“SIP/103-00000095”, “CDR(cnam)=Ext 103”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-user-callerid:32] Set(“SIP/103-00000095”, “CHANNEL(language)=en”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-exten-vm:2] Set(“SIP/103-00000095”, “RingGroupMethod=none”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-exten-vm:3] Set(“SIP/103-00000095”, “__EXTTOCALL=100”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-exten-vm:4] Set(“SIP/103-00000095”, “__PICKUPMARK=100”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-exten-vm:5] Set(“SIP/103-00000095”, “RT=”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-exten-vm:6] Gosub(“SIP/103-00000095”, “sub-record-check,s,1(exten,100,)”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@sub-record-check:1] Set(“SIP/103-00000095”, “REC_POLICY_MODE_SAVE=”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@sub-record-check:2] GotoIf(“SIP/103-00000095”, “1?check”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Goto (sub-record-check,s,7)
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@sub-record-check:7] Set(“SIP/103-00000095”, “__MON_FMT=wav”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@sub-record-check:8] GotoIf(“SIP/103-00000095”, “1?next”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Goto (sub-record-check,s,11)
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@sub-record-check:11] ExecIf(“SIP/103-00000095”, “0?Return()”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@sub-record-check:12] ExecIf(“SIP/103-00000095”, “0?Set(__REC_POLICY_MODE=)”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@sub-record-check:13] GotoIf(“SIP/103-00000095”, “0?exten,1”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@sub-record-check:14] Set(“SIP/103-00000095”, “__REC_STATUS=INITIALIZED”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@sub-record-check:15] Set(“SIP/103-00000095”, “NOW=1372070714”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@sub-record-check:16] Set(“SIP/103-00000095”, “__DAY=24”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@sub-record-check:17] Set(“SIP/103-00000095”, “__MONTH=06”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@sub-record-check:18] Set(“SIP/103-00000095”, “__YEAR=2013”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@sub-record-check:19] Set(“SIP/103-00000095”, “__TIMESTR=20130624-114514”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@sub-record-check:20] Set(“SIP/103-00000095”, “__FROMEXTEN=103”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@sub-record-check:21] Set(“SIP/103-00000095”, “__CALLFILENAME=exten-100-103-20130624-114514-1372070714.149”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@sub-record-check:22] Goto(“SIP/103-00000095”, “exten,1”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Goto (sub-record-check,exten,1)
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [exten@sub-record-check:1] GotoIf(“SIP/103-00000095”, “0?callee”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [exten@sub-record-check:2] Set(“SIP/103-00000095”, “__REC_POLICY_MODE=dontcare”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [exten@sub-record-check:3] GotoIf(“SIP/103-00000095”, “1?caller”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Goto (sub-record-check,exten,10)
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [exten@sub-record-check:10] Set(“SIP/103-00000095”, “__REC_POLICY_MODE=dontcare”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [exten@sub-record-check:11] GosubIf(“SIP/103-00000095”, “0?record,1(exten,100,103)”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [exten@sub-record-check:12] Return(“SIP/103-00000095”, “”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-exten-vm:7] GotoIf(“SIP/103-00000095”, “1?macrodial”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Goto (macro-exten-vm,s,13)
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-exten-vm:13] GosubIf(“SIP/103-00000095”, “0?clrheader,1()”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-exten-vm:14] Macro(“SIP/103-00000095”, “dial-one,Ttr,100”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-dial-one:1] Set(“SIP/103-00000095”, “DEXTEN=100”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-dial-one:2] Set(“SIP/103-00000095”, “DIALSTATUS_CW=”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-dial-one:3] GosubIf(“SIP/103-00000095”, “0?screen,1()”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-dial-one:4] GosubIf(“SIP/103-00000095”, “0?cf,1()”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-dial-one:5] GotoIf(“SIP/103-00000095”, “1?skip1”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Goto (macro-dial-one,s,8)
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-dial-one:8] GotoIf(“SIP/103-00000095”, “0?nodial”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-dial-one:9] GotoIf(“SIP/103-00000095”, “0?continue”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-dial-one:10] Set(“SIP/103-00000095”, “EXTHASCW=ENABLED”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-dial-one:11] GotoIf(“SIP/103-00000095”, “0?next1:cwinusebusy”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Goto (macro-dial-one,s,23)
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-dial-one:23] GotoIf(“SIP/103-00000095”, “1?next3:continue”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Goto (macro-dial-one,s,24)
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-dial-one:24] ExecIf(“SIP/103-00000095”, “0?Set(DIALSTATUS_CW=BUSY)”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-dial-one:25] GotoIf(“SIP/103-00000095”, “0?nodial”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-dial-one:26] GosubIf(“SIP/103-00000095”, “1?dstring,1():dlocal,1()”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [dstring@macro-dial-one:1] Set(“SIP/103-00000095”, “DSTRING=”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [dstring@macro-dial-one:2] Set(“SIP/103-00000095”, “DEVICES=100”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [dstring@macro-dial-one:3] ExecIf(“SIP/103-00000095”, “0?Return()”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [dstring@macro-dial-one:4] ExecIf(“SIP/103-00000095”, “0?Set(DEVICES=00)”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [dstring@macro-dial-one:5] Set(“SIP/103-00000095”, “LOOPCNT=1”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [dstring@macro-dial-one:6] Set(“SIP/103-00000095”, “ITER=1”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [dstring@macro-dial-one:7] Set(“SIP/103-00000095”, “THISDIAL=SIP/100”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [dstring@macro-dial-one:8] GosubIf(“SIP/103-00000095”, “1?zap2dahdi,1()”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [zap2dahdi@macro-dial-one:1] ExecIf(“SIP/103-00000095”, “0?Return()”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [zap2dahdi@macro-dial-one:2] Set(“SIP/103-00000095”, “NEWDIAL=”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [zap2dahdi@macro-dial-one:3] Set(“SIP/103-00000095”, “LOOPCNT2=1”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [zap2dahdi@macro-dial-one:4] Set(“SIP/103-00000095”, “ITER2=1”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [zap2dahdi@macro-dial-one:5] Set(“SIP/103-00000095”, “THISPART2=SIP/100”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [zap2dahdi@macro-dial-one:6] ExecIf(“SIP/103-00000095”, “0?Set(THISPART2=DAHDI/100)”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [zap2dahdi@macro-dial-one:7] Set(“SIP/103-00000095”, “NEWDIAL=SIP/100&”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [zap2dahdi@macro-dial-one:8] Set(“SIP/103-00000095”, “ITER2=2”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [zap2dahdi@macro-dial-one:9] GotoIf(“SIP/103-00000095”, “0?begin2”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [zap2dahdi@macro-dial-one:10] Set(“SIP/103-00000095”, “THISDIAL=SIP/100”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [zap2dahdi@macro-dial-one:11] Return(“SIP/103-00000095”, “”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [dstring@macro-dial-one:9] Set(“SIP/103-00000095”, “DSTRING=SIP/100&”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [dstring@macro-dial-one:10] Set(“SIP/103-00000095”, “ITER=2”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [dstring@macro-dial-one:11] GotoIf(“SIP/103-00000095”, “0?begin”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [dstring@macro-dial-one:12] Set(“SIP/103-00000095”, “DSTRING=SIP/100”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [dstring@macro-dial-one:13] Return(“SIP/103-00000095”, “”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-dial-one:27] GotoIf(“SIP/103-00000095”, “0?nodial”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-dial-one:28] GotoIf(“SIP/103-00000095”, “0?skiptrace”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-dial-one:29] GosubIf(“SIP/103-00000095”, “1?ctset,1():ctclear,1()”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [ctset@macro-dial-one:1] Set(“SIP/103-00000095”, “DB(CALLTRACE/100)=103”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [ctset@macro-dial-one:2] Return(“SIP/103-00000095”, “”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-dial-one:30] Set(“SIP/103-00000095”, “D_OPTIONS=Ttr”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-dial-one:31] ExecIf(“SIP/103-00000095”, “0?SIPAddHeader(Alert-Info: )”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-dial-one:32] ExecIf(“SIP/103-00000095”, “0?SIPAddHeader()”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-dial-one:33] ExecIf(“SIP/103-00000095”, “0?Set(CHANNEL(musicclass)=)”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-dial-one:34] GosubIf(“SIP/103-00000095”, “0?qwait,1()”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-dial-one:35] Set(“SIP/103-00000095”, “__CWIGNORE=”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-dial-one:36] Set(“SIP/103-00000095”, “__KEEPCID=TRUE”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-dial-one:37] GotoIf(“SIP/103-00000095”, “0?usegoto,1”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-dial-one:38] GotoIf(“SIP/103-00000095”, “0?godial”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-dial-one:39] Set(“SIP/103-00000095”, “CONNECTEDLINE(name,i)=Ext 100”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-dial-one:40] Set(“SIP/103-00000095”, “CONNECTEDLINE(num)=100”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-dial-one:41] Set(“SIP/103-00000095”, “D_OPTIONS=TtrI”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] pbx.c: – Executing [s@macro-dial-one:42] Dial(“SIP/103-00000095”, “SIP/100,TtrI”) in new stack
[2013-06-24 11:45:14] VERBOSE[26964] netsock2.c: == Using SIP VIDEO TOS bits 136
[2013-06-24 11:45:14] VERBOSE[26964] netsock2.c: == Using SIP VIDEO CoS mark 6
[2013-06-24 11:45:14] VERBOSE[26964] netsock2.c: == Using SIP RTP TOS bits 184
[2013-06-24 11:45:14] VERBOSE[26964] netsock2.c: == Using SIP RTP CoS mark 5
[2013-06-24 11:45:14] VERBOSE[26964] app_dial.c: – Called SIP/100
[2013-06-24 11:45:14] VERBOSE[26964] app_dial.c: – Connected line update to SIP/103-00000095 prevented.
[2013-06-24 11:45:15] VERBOSE[26964] app_dial.c: – SIP/100-00000096 is ringing
[2013-06-24 11:45:19] WARNING[1749] chan_sip.c: Ignoring video media offer because port number is zero
[2013-06-24 11:45:19] VERBOSE[26964] app_dial.c: – Connected line update to SIP/103-00000095 prevented.
[2013-06-24 11:45:19] VERBOSE[26964] app_dial.c: – SIP/100-00000096 answered SIP/103-00000095
[2013-06-24 11:45:26] WARNING[1749] chan_sip.c: Retransmission timeout reached on transmission [email protected] for seqno 2 (Critical Response) – See https://wiki.asterisk.org/wiki/display/AST/SIP+Retransmissions
Packet timed out after 6400ms with no response
[2013-06-24 11:45:26] WARNING[1749] chan_sip.c: Hanging up call [email protected] - no reply to our critical packet (see https://wiki.asterisk.org/wiki/display/AST/SIP+Retransmissions).
[2013-06-24 11:45:26] VERBOSE[26964] pbx.c: – Executing [h@macro-dial-one:1] Macro(“SIP/103-00000095”, “hangupcall,”) in new stack
[2013-06-24 11:45:26] VERBOSE[26964] pbx.c: – Executing [s@macro-hangupcall:1] GotoIf(“SIP/103-00000095”, “1?theend”) in new stack
[2013-06-24 11:45:26] VERBOSE[26964] pbx.c: – Goto (macro-hangupcall,s,3)
[2013-06-24 11:45:26] VERBOSE[26964] pbx.c: – Executing [s@macro-hangupcall:3] ExecIf(“SIP/103-00000095”, “0?Set(CDR(recordingfile)=)”) in new stack
[2013-06-24 11:45:26] VERBOSE[26964] pbx.c: – Executing [s@macro-hangupcall:4] Hangup(“SIP/103-00000095”, “”) in new stack
[2013-06-24 11:45:26] VERBOSE[26964] app_macro.c: == Spawn extension (macro-hangupcall, s, 4) exited non-zero on ‘SIP/103-00000095’ in macro ‘hangupcall’
[2013-06-24 11:45:26] VERBOSE[26964] features.c: == Spawn extension (macro-dial-one, h, 1) exited non-zero on ‘SIP/103-00000095’
[2013-06-24 11:45:26] VERBOSE[26964] app_macro.c: == Spawn extension (macro-dial-one, s, 42) exited non-zero on ‘SIP/103-00000095’ in macro ‘dial-one’
[2013-06-24 11:45:26] VERBOSE[26964] app_macro.c: == Spawn extension (macro-exten-vm, s, 14) exited non-zero on ‘SIP/103-00000095’ in macro ‘exten-vm’
[2013-06-24 11:45:26] VERBOSE[26964] pbx.c: == Spawn extension (from-internal, 100, 2) exited non-zero on ‘SIP/103-00000095’
[2013-06-24 11:47:55] VERBOSE[1619] asterisk.c: – Remote UNIX connection
[2013-06-24 11:47:55] VERBOSE[27023] asterisk.c: – Remote UNIX connection disconnected

9

I should also say that the above log was taken from two handsets on either side of a VPN connection. The freepbx server is at one site, along with one of the handsets, and the other phone is at another site.

There was no packet loss or network issue during the call at all.

Olly

10

It turned out to be that the other site wasn’t listed in the local network settings.

That fixed it for us.

Olly

11

It turned out that the pfsense firewall was the culprit for us. The firewall allows for the automatic outbound NAT rule generation(IPsec passthrough included). The problem is that this randomises the ports the traffic is sent out on.
Disabling this setting has resolved the issue. :slight_smile: