Misc destinations not working

General Help
1

Hey guys,

Our system is working great with the exception of one part.
We have an after hours service that we need to direct our calls after certain time or at night.
When this happens, the caller just hears and empty space, there is no trilling nor anything else, rarely the destination rings, you cant hear the caller, nor the caller the callee.

Most of the time the call just doesnt reach the destination, as the destination never rings. Very rarely and rndom does the destination ring, maybe 1 out of 30 tries.

I have some debug in case you see anything, but its so long that I dont know which part to provide, and I dont want to have 16 pages of code in this thread for clarity sake.

What do you guys think I should look for?

TIA!

2

A single problem call trace:
https://wiki.freepbx.org/display/SUP/Providing+Great+Debug#ProvidingGreatDebug-AsteriskLogs

3

Here is a debug of the entire process.

<— SIP read from UDP:162.XXX.144.XXX:5060 —>
INVITE sip:[email protected] SIP/2.0
Via: SIP/2.0/UDP 162.XXX.144.XXX:5060;branch=z9hG4bK60453d2c;rport
Max-Forwards: 70
From: “XXX3422069” <sip:[email protected] >;tag=as35dfaf48
To: sip:[email protected]
Contact: sip:[email protected]:5060
Call-ID: [email protected]:5060
CSeq: 102 INVITE
User-Agent: voipXXX.XXX
Date: Sat, 21 Jul 2018 13:24:37 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Remote-Party-ID: “XXX3422069” sip:[email protected];party=calling;privacy=off;screen=no
Content-Type: application/sdp
Content-Length: 227

v=0
o=root 610712806 610712806 IN IP4 162.XXX.144.XXX
s=VOIPProvider.com
c=IN IP4 162.XXX.144.XXX
t=0 0
m=audio 19060 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
<------------->
— (15 headers 11 lines) —
Sending to 162.XXX.144.XXX:5060 (NAT)
Sending to 162.XXX.144.XXX:5060 (NAT)
Using INVITE request as basis request - [email protected]:5060
Found peer ‘voip’ for ‘XXX3422069’ from 162.XXX.144.XXX:5060
Found RTP audio format 0
Found RTP audio format 101
Found audio description format PCMU for ID 0
Found audio description format telephone-event for ID 101
Capabilities: us - (ulaw|g729), peer - audio=(ulaw)/video=(nothing)/text=(nothing), combined - (ulaw)
Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|)
Peer audio RTP is at port 162.XXX.144.XXX:19060
Looking for XXX5527866 in from-trunk (domain 50.248.XX.XX)
sip_route_dump: route/path hop: sip:[email protected]:5060

<— Transmitting (NAT) to 162.XXX.144.XXX:5060 —>
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 162.XXX.144.XXX:5060;branch=z9hG4bK60453d2c;received=162.XXX.144.XXX;rport=5060
From: “XXX3422069” sip:[email protected];tag=as35dfaf48
To: sip:[email protected]
Call-ID: [email protected]:5060
CSeq: 102 INVITE
Server: FPBX-13.0.195.4(13.17.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: sip:[email protected]:5160
Content-Length: 0

<------------>
[2018-07-21 09:24:37] WARNING[22241][C-00000071]: Ext. XXX5527866:2 @ from-trunk: Friendly Scanner from 162.XXX.144.XXX
Audio is at 14798
Adding codec ulaw to SDP
Adding codec g729 to SDP
Adding non-codec 0x1 (telephone-event) to SDP
Reliably Transmitting (NAT) to 162.XXX.144.XXX:5060:
INVITE sip:[email protected] SIP/2.0
Via: SIP/2.0/UDP 192.168.XXX.XXX:5160;branch=z9hG4bK4e645e88;rport
Max-Forwards: 70
From: sip:[email protected]:5160;tag=as25643263
To: sip:[email protected]
Contact: sip:[email protected]:5160
Call-ID: [email protected]:5160
CSeq: 102 INVITE
User-Agent: FPBX-13.0.195.4(13.17.0)
Date: Sat, 21 Jul 2018 13:24:38 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Remote-Party-ID: “XXX5527866” sip:[email protected];party=calling;privacy=off;screen=no
Content-Type: application/sdp
Content-Length: 299

v=0
o=root 752208669 752208669 IN IP4 192.168.XXX.XXX
s=Asterisk PBX 13.17.0
c=IN IP4 192.168.XXX.XXX
t=0 0
m=audio 14798 RTP/AVP 0 18 101
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

Retransmitting #1 (NAT) to 162.XXX.144.XXX:5060:
INVITE sip:[email protected] SIP/2.0
Via: SIP/2.0/UDP 192.168.XXX.XXX:5160;branch=z9hG4bK4e645e88;rport
Max-Forwards: 70
From: sip:[email protected]:5160;tag=as25643263
To: sip:[email protected]
Contact: sip:[email protected]:5160
Call-ID: [email protected]:5160
CSeq: 102 INVITE
User-Agent: FPBX-13.0.195.4(13.17.0)
Date: Sat, 21 Jul 2018 13:24:38 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Remote-Party-ID: “XXX5527866” sip:[email protected];party=calling;privacy=off;screen=no
Content-Type: application/sdp
Content-Length: 299

v=0
o=root 752208669 752208669 IN IP4 192.168.XXX.XXX
s=Asterisk PBX 13.17.0
c=IN IP4 192.168.XXX.XXX
t=0 0
m=audio 14798 RTP/AVP 0 18 101
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

Retransmitting #2 (NAT) to 162.XXX.144.XXX:5060:
INVITE sip:[email protected] SIP/2.0
Via: SIP/2.0/UDP 192.168.XXX.XXX:5160;branch=z9hG4bK4e645e88;rport
Max-Forwards: 70
From: sip:[email protected]:5160;tag=as25643263
To: sip:[email protected]
Contact: sip:[email protected]:5160
Call-ID: [email protected]:5160
CSeq: 102 INVITE
User-Agent: FPBX-13.0.195.4(13.17.0)
Date: Sat, 21 Jul 2018 13:24:38 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Remote-Party-ID: “XXX5527866” sip:[email protected];party=calling;privacy=off;screen=no
Content-Type: application/sdp
Content-Length: 299

v=0
o=root 752208669 752208669 IN IP4 192.168.XXX.XXX
s=Asterisk PBX 13.17.0
c=IN IP4 192.168.XXX.XXX
t=0 0
m=audio 14798 RTP/AVP 0 18 101
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

Retransmitting #3 (NAT) to 162.XXX.144.XXX:5060:
INVITE sip:[email protected] SIP/2.0
Via: SIP/2.0/UDP 192.168.XXX.XXX:5160;branch=z9hG4bK4e645e88;rport
Max-Forwards: 70
From: sip:[email protected]:5160;tag=as25643263
To: sip:[email protected]
Contact: sip:[email protected]:5160
Call-ID: [email protected]:5160
CSeq: 102 INVITE
User-Agent: FPBX-13.0.195.4(13.17.0)
Date: Sat, 21 Jul 2018 13:24:38 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Remote-Party-ID: “XXX5527866” sip:[email protected];party=calling;privacy=off;screen=no
Content-Type: application/sdp
Content-Length: 299

v=0
o=root 752208669 752208669 IN IP4 192.168.XXX.XXX
s=Asterisk PBX 13.17.0
c=IN IP4 192.168.XXX.XXX
t=0 0
m=audio 14798 RTP/AVP 0 18 101
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

Retransmitting #4 (NAT) to 162.XXX.144.XXX:5060:
INVITE sip:[email protected] SIP/2.0
Via: SIP/2.0/UDP 192.168.XXX.XXX:5160;branch=z9hG4bK4e645e88;rport
Max-Forwards: 70
From: sip:[email protected]:5160;tag=as25643263
To: sip:[email protected]
Contact: sip:[email protected]:5160
Call-ID: [email protected]:5160
CSeq: 102 INVITE
User-Agent: FPBX-13.0.195.4(13.17.0)
Date: Sat, 21 Jul 2018 13:24:38 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Remote-Party-ID: “XXX5527866” sip:[email protected];party=calling;privacy=off;screen=no
Content-Type: application/sdp
Content-Length: 299

v=0
o=root 752208669 752208669 IN IP4 192.168.XXX.XXX
s=Asterisk PBX 13.17.0
c=IN IP4 192.168.XXX.XXX
t=0 0
m=audio 14798 RTP/AVP 0 18 101
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

Retransmitting #5 (NAT) to 162.XXX.144.XXX:5060:
INVITE sip:[email protected] SIP/2.0
Via: SIP/2.0/UDP 192.168.XXX.XXX:5160;branch=z9hG4bK4e645e88;rport
Max-Forwards: 70
From: sip:[email protected]:5160;tag=as25643263
To: sip:[email protected]
Contact: sip:[email protected]:5160
Call-ID: [email protected]:5160
CSeq: 102 INVITE
User-Agent: FPBX-13.0.195.4(13.17.0)
Date: Sat, 21 Jul 2018 13:24:38 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Remote-Party-ID: “XXX5527866” sip:[email protected];party=calling;privacy=off;screen=no
Content-Type: application/sdp
Content-Length: 299

v=0
o=root 752208669 752208669 IN IP4 192.168.XXX.XXX
s=Asterisk PBX 13.17.0
c=IN IP4 192.168.XXX.XXX
t=0 0
m=audio 14798 RTP/AVP 0 18 101
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

<— SIP read from UDP:162.XXX.144.XXX:5060 —>
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 192.168.XXX.XXX:5160;branch=z9hG4bK4e645e88;received=50.248.XX.XX;rport=5524
From: sip:[email protected]:5160;tag=as25643263
To: sip:[email protected];tag=as261c1ea1
Call-ID: [email protected]:5160
CSeq: 102 INVITE
Server: VOIPProvider.com
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm=“tampanew2.VOIPProvider.com”, nonce=“31a424f9”
Content-Length: 0

<------------->
— (11 headers 0 lines) —
Transmitting (NAT) to 162.XXX.144.XXX:5060:
ACK sip:[email protected] SIP/2.0
Via: SIP/2.0/UDP 192.168.XXX.XXX:5160;branch=z9hG4bK4e645e88;rport
Max-Forwards: 70
From: sip:[email protected]:5160;tag=as25643263
To: sip:[email protected];tag=as261c1ea1
Contact: sip:[email protected]:5160
Call-ID: [email protected]:5160
CSeq: 102 ACK
User-Agent: FPBX-13.0.195.4(13.17.0)
Content-Length: 0

Audio is at 14798
Adding codec ulaw to SDP
Adding codec g729 to SDP
Adding non-codec 0x1 (telephone-event) to SDP
Reliably Transmitting (NAT) to 162.XXX.144.XXX:5060:
INVITE sip:[email protected] SIP/2.0
Via: SIP/2.0/UDP 192.168.XXX.XXX:5160;branch=z9hG4bK5b8a9e33;rport
Max-Forwards: 70
From: sip:[email protected]:5160;tag=as25643263
To: sip:[email protected]
Contact: sip:[email protected]:5160
Call-ID: [email protected]:5160
CSeq: 103 INVITE
User-Agent: FPBX-13.0.195.4(13.17.0)
Authorization: Digest username=“XXX555”, realm=“tampanew2.VOIPProvider.com”, algorithm=MD5, uri="sip:[email protected]", nonce=“31a424f9”, response=“593e98842ffd809bbfc48a2fff559215”
Date: Sat, 21 Jul 2018 13:24:41 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Remote-Party-ID: “XXX5527866” sip:[email protected];party=calling;privacy=off;screen=no
Content-Type: application/sdp
Content-Length: 299

v=0
o=root 752208669 752208670 IN IP4 192.168.XXX.XXX
s=Asterisk PBX 13.17.0
c=IN IP4 192.168.XXX.XXX
t=0 0
m=audio 14798 RTP/AVP 0 18 101
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

<— SIP read from UDP:162.XXX.144.XXX:5060 —>
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.XXX.XXX:5160;branch=z9hG4bK5b8a9e33;received=50.248.XX.XX;rport=5524
From: sip:[email protected]:5160;tag=as25643263
To: sip:[email protected]
Call-ID: [email protected]:5160
CSeq: 103 INVITE
Server: VOIPProvider.com
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: sip:[email protected]:5060
Content-Length: 0

<------------->
— (12 headers 0 lines) —

<— SIP read from UDP:162.XXX.144.XXX:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.XXX.XXX:5160;branch=z9hG4bK5b8a9e33;received=50.248.XX.XX;rport=5524
From: sip:[email protected]:5160;tag=as25643263
To: sip:[email protected];tag=as52806dcc
Call-ID: [email protected]:5160
CSeq: 103 INVITE
Server: VOIPProvider.com
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: sip:[email protected]:5060
Remote-Party-ID: “XXX6677400” sip:[email protected];party=called;privacy=off;screen=no
Content-Type: application/sdp
Require: timer
Content-Length: 229

v=0
o=root 1224788409 1224788409 IN IP4 162.XXX.144.XXX
s=VOIPProvider.com
c=IN IP4 162.XXX.144.XXX
t=0 0
m=audio 12062 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
<------------->
— (15 headers 11 lines) —
Found RTP audio format 0
Found RTP audio format 101
Found audio description format PCMU for ID 0
Found audio description format telephone-event for ID 101
Capabilities: us - (ulaw|g729), peer - audio=(ulaw)/video=(nothing)/text=(nothing), combined - (ulaw)
Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|)
Peer audio RTP is at port 162.XXX.144.XXX:12062
sip_route_dump: route/path hop: sip:[email protected]:5060
Transmitting (NAT) to 162.XXX.144.XXX:5060:
ACK sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.XXX.XXX:5160;branch=z9hG4bK58132f1b;rport
Max-Forwards: 70
From: sip:[email protected]:5160;tag=as25643263
To: sip:[email protected];tag=as52806dcc
Contact: sip:[email protected]:5160
Call-ID: [email protected]:5160
CSeq: 103 ACK
User-Agent: FPBX-13.0.195.4(13.17.0)
Content-Length: 0

Audio is at 17200
Adding codec ulaw to SDP
Adding non-codec 0x1 (telephone-event) to SDP

<— Reliably Transmitting (NAT) to 162.XXX.144.XXX:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 162.XXX.144.XXX:5060;branch=z9hG4bK60453d2c;received=162.XXX.144.XXX;rport=5060
From: “XXX3422069” sip:[email protected];tag=as35dfaf48
To: sip:[email protected];tag=as45485e4c
Call-ID: [email protected]:5060
CSeq: 102 INVITE
Server: FPBX-13.0.195.4(13.17.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: sip:[email protected]:5160
Remote-Party-ID: “XXX6677400” sip:[email protected];party=called;privacy=off;screen=no
Content-Type: application/sdp
Require: timer
Content-Length: 252

v=0
o=root 258736345 258736345 IN IP4 192.168.XXX.XXX
s=Asterisk PBX 13.17.0
c=IN IP4 192.168.XXX.XXX
t=0 0
m=audio 17200 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

<------------>

<— SIP read from UDP:162.XXX.144.XXX:5060 —>
ACK sip:[email protected]:5160 SIP/2.0
Via: SIP/2.0/UDP 162.XXX.144.XXX:5060;branch=z9hG4bK1e8d994e;rport
Max-Forwards: 70
From: “XXX3422069” sip:[email protected];tag=as35dfaf48
To: sip:[email protected];tag=as45485e4c
Contact: sip:[email protected]:5060
Call-ID: [email protected]:5060
CSeq: 102 ACK
User-Agent: VOIPProvider.com
Content-Length: 0

<------------->
— (10 headers 0 lines) —

<— SIP read from UDP:162.XXX.144.XXX:5060 —>
BYE sip:[email protected]:5160 SIP/2.0
Via: SIP/2.0/UDP 162.XXX.144.XXX:5060;branch=z9hG4bK7e06996e;rport
Max-Forwards: 70
From: “XXX3422069” sip:[email protected];tag=as35dfaf48
To: sip:[email protected];tag=as45485e4c
Call-ID: [email protected]:5060
CSeq: 103 BYE
User-Agent: VOIPProvider.com
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16
Content-Length: 0

<------------->
— (11 headers 0 lines) —
Sending to 162.XXX.144.XXX:5060 (NAT)
Scheduling destruction of SIP dialog ‘11005783154cb80[email protected]:5060’ in 6400 ms (Method: BYE)

<— Transmitting (NAT) to 162.XXX.144.XXX:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 162.XXX.144.XXX:5060;branch=z9hG4bK7e06996e;received=162.XXX.144.XXX;rport=5060
From: “XXX3422069” sip:[email protected];tag=as35dfaf48
To: sip:[email protected];tag=as45485e4c
Call-ID: [email protected]:5060
CSeq: 103 BYE
Server: FPBX-13.0.195.4(13.17.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0

<------------>
Scheduling destruction of SIP dialog ‘65b231e030bbee9345[email protected]:5160’ in 6400 ms (Method: INVITE)
Reliably Transmitting (NAT) to 162.XXX.144.XXX:5060:
BYE sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.XXX.XXX:5160;branch=z9hG4bK684c65b6;rport
Max-Forwards: 70
From: sip:[email protected]:5160;tag=as25643263
To: sip:[email protected];tag=as52806dcc
Call-ID: [email protected]:5160
CSeq: 104 BYE
User-Agent: FPBX-13.0.195.4(13.17.0)
Authorization: Digest username=“XXX555”, realm=“tampanew2.VOIPProvider.com”, algorithm=MD5, uri=“sip:[email protected]:5060”, nonce=“31a424f9”, response=“32c2f2e060f0f5c018a233733109b43f”
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16
Content-Length: 0

[2018-07-21 09:24:47] NOTICE[2184]: chan_sip.c:15722 sip_reregister: – Re-registration for [email protected]
REGISTER 12 headers, 0 lines
Reliably Transmitting (NAT) to 162.XXX.144.XXX:5060:
REGISTER sip:tampa2.VOIPProvider.com SIP/2.0
Via: SIP/2.0/UDP 192.168.XXX.XXX:5160;branch=z9hG4bK1501e381;rport
Max-Forwards: 70
From: sip:[email protected];tag=as1de19e9f
To: sip:[email protected]
Call-ID: 071edb9233a5a1a85698306c47e9efab@[::1]
CSeq: 106 REGISTER
Supported: replaces, timer
User-Agent: FPBX-13.0.195.4(13.17.0)
Authorization: Digest username=“XXX555”, realm=“tampanew2.VOIPProvider.com”, algorithm=MD5, uri=“sip:tampa2.VOIPProvider.com”, nonce=“0d5e9c75”, response=“3b46971698da0c18a3a52e6fb2876873”
Expires: 120
Contact: sip:[email protected]:5160
Content-Length: 0

<— SIP read from UDP:162.XXX.144.XXX:5060 —>
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 192.168.XXX.XXX:5160;branch=z9hG4bK1501e381;received=50.248.XX.XX;rport=5524
From: sip:[email protected];tag=as1de19e9f
To: sip:[email protected];tag=as64d775a5
Call-ID: 071edb9233a5a1a85698306c47e9efab@[::1]
CSeq: 106 REGISTER
Server: VOIPProvider.com
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm=“tampanew2.VOIPProvider.com”, nonce=“78f47290”
Content-Length: 0

<------------->
— (11 headers 0 lines) —
Responding to challenge, registration to domain/host name tampa2.VOIPProvider.com
REGISTER 12 headers, 0 lines
Reliably Transmitting (NAT) to 162.XXX.144.XXX:5060:
REGISTER sip:tampa2.VOIPProvider.com SIP/2.0
Via: SIP/2.0/UDP 192.168.XXX.XXX:5160;branch=z9hG4bK7528fdd5;rport
Max-Forwards: 70
From: sip:[email protected];tag=as1de19e9f
To: sip:[email protected]
Call-ID: 071edb9233a5a1a85698306c47e9efab@[::1]
CSeq: 107 REGISTER
Supported: replaces, timer
User-Agent: FPBX-13.0.195.4(13.17.0)
Authorization: Digest username=“XXX555”, realm=“tampanew2.VOIPProvider.com”, algorithm=MD5, uri=“sip:tampa2.VOIPProvider.com”, nonce=“78f47290”, response=“4ed64b8e198db3a71b8c4b2ec9e6d79c”
Expires: 120
Contact: sip:[email protected]:5160
Content-Length: 0

<— SIP read from UDP:162.XXX.144.XXX:5060 —>
OPTIONS sip:[email protected]:5160 SIP/2.0
Via: SIP/2.0/UDP 162.XXX.144.XXX:5060;branch=z9hG4bK78b3c9ea;rport
Max-Forwards: 70
From: “Unknown” sip:[email protected];tag=as3c6576aa
To: sip:[email protected]:5160
Contact: sip:[email protected]:5060
Call-ID: [email protected]:5060
CSeq: 102 OPTIONS
User-Agent: VOIPProvider.com
Date: Sat, 21 Jul 2018 13:24:47 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0

<------------->
— (13 headers 0 lines) —
Sending to 162.XXX.144.XXX:5060 (NAT)
Looking for s in from-sip-external (domain 192.168.XXX.XXX)

<— Transmitting (NAT) to 162.XXX.144.XXX:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 162.XXX.144.XXX:5060;branch=z9hG4bK78b3c9ea;received=162.XXX.144.XXX;rport=5060
From: “Unknown” sip:[email protected];tag=as3c6576aa
To: sip:[email protected]:5160;tag=as2f68a0cb
Call-ID: [email protected]:5060
CSeq: 102 OPTIONS
Server: FPBX-13.0.195.4(13.17.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Contact: sip:192.168.XXX.XXX:5160
Accept: application/sdp
Content-Length: 0

<------------>
Scheduling destruction of SIP dialog ‘6cd0d519712949e626ca[email protected]:5060’ in 32000 ms (Method: OPTIONS)

<— SIP read from UDP:162.XXX.144.XXX:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.XXX.XXX:5160;branch=z9hG4bK7528fdd5;received=50.248.XX.XX;rport=5524
From: sip:[email protected];tag=as1de19e9f
To: sip:[email protected];tag=as64d775a5
Call-ID: 071edb9233a5a1a85698306c47e9efab@[::1]
CSeq: 107 REGISTER
Server: VOIPProvider.com
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Expires: 120
Contact: sip:[email protected]:5160;expires=120
Date: Sat, 21 Jul 2018 13:24:47 GMT
Content-Length: 0

<------------->
— (13 headers 0 lines) —
[2018-07-21 09:24:47] NOTICE[2184]: chan_sip.c:24538 handle_response_register: Outbound Registration: Expiry for tampa2.VOIPProvider.com is 120 sec (Scheduling reregistration in 105 s)
Really destroying SIP dialog ‘071edb9233a5a1a85698306c47e9efab@[::1]’ Method: REGISTER

<— SIP read from UDP:162.XXX.144.XXX:5060 —>
BYE sip:[email protected]:5160 SIP/2.0
Via: SIP/2.0/UDP 162.XXX.144.XXX:5060;branch=z9hG4bK7e06996e;rport
Max-Forwards: 70
From: “XXX3422069” sip:[email protected];tag=as35dfaf48
To: sip:[email protected];tag=as45485e4c
Call-ID: [email protected]:5060
CSeq: 103 BYE
User-Agent: VOIPProvider.com
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16
Content-Length: 0

<------------->
— (11 headers 0 lines) —
Sending to 162.XXX.144.XXX:5060 (NAT)

<— Transmitting (NAT) to 162.XXX.144.XXX:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 162.XXX.144.XXX:5060;branch=z9hG4bK7e06996e;received=162.XXX.144.XXX;rport=5060
From: “XXX3422069” sip:[email protected];tag=as35dfaf48
To: sip:[email protected];tag=as45485e4c
Call-ID: [email protected]:5060
CSeq: 103 BYE
Server: FPBX-13.0.195.4(13.17.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0

<------------>
Retransmitting #1 (NAT) to 162.XXX.144.XXX:5060:
BYE sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.XXX.XXX:5160;branch=z9hG4bK684c65b6;rport
Max-Forwards: 70
From: sip:[email protected]:5160;tag=as25643263
To: sip:[email protected];tag=as52806dcc
Call-ID: [email protected]:5160
CSeq: 104 BYE
User-Agent: FPBX-13.0.195.4(13.17.0)
Authorization: Digest username=“XXX555”, realm=“tampanew2.VOIPProvider.com”, algorithm=MD5, uri=“sip:[email protected]:5060”, nonce=“31a424f9”, response=“32c2f2e060f0f5c018a233733109b43f”
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16
Content-Length: 0

<— SIP read from UDP:162.XXX.144.XXX:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.XXX.XXX:5160;branch=z9hG4bK684c65b6;received=50.248.XX.XX;rport=5524
From: sip:[email protected]:5160;tag=as25643263
To: sip:[email protected];tag=as52806dcc
Call-ID: [email protected]:5160
CSeq: 104 BYE
Server: VOIPProvider.com
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0

4

When troubleshooting applications, it’s usually better to give us the ‘/var/log/asterisk/full’ log instead of a SIP dump. This way, we can see what the system is doing instead of seeing what the call is doing.

5

OK here it is:

[2018-07-23 14:32:04] VERBOSE[14199][C-0000000f] pbx.c: Executing [s@crm-hangup:3] ExecIf("SIP/VOIPProvider-00000011", "0?Set(__CRM_VOICEMAIL=)") in new stack
[2018-07-23 14:32:04] VERBOSE[14199][C-0000000f] pbx.c: Executing [s@crm-hangup:4] NoOp("SIP/VOIPProvider-00000011", "MASTER CHANNEL: 1532370708.23 = 1532370708.23") in new stack
[2018-07-23 14:32:04] VERBOSE[14199][C-0000000f] pbx.c: Executing [s@crm-hangup:5] GotoIf("SIP/VOIPProvider-00000011", "0?return") in new stack
[2018-07-23 14:32:04] VERBOSE[14199][C-0000000f] pbx.c: Executing [s@crm-hangup:6] Set("SIP/VOIPProvider-00000011", "__CRM_HANGUP=1") in new stack
[2018-07-23 14:32:04] VERBOSE[14199][C-0000000f] pbx.c: Executing [s@crm-hangup:7] AGI("SIP/VOIPProvider-00000011", "sangomacrm.agi") in new stack
[2018-07-23 14:32:04] VERBOSE[14199][C-0000000f] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/sangomacrm.agi
[2018-07-23 14:32:04] VERBOSE[14199][C-0000000f] res_agi.c: <SIP/VOIPProvider-00000011>AGI Script sangomacrm.agi completed, returning 0
[2018-07-23 14:32:05] VERBOSE[14199][C-0000000f] pbx.c: Executing [s@crm-hangup:8] Return("SIP/VOIPProvider-00000011", "") in new stack
[2018-07-23 14:32:05] VERBOSE[14199][C-0000000f] app_stack.c: Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/VOIPProvider-00000011'
[2018-07-23 14:32:05] VERBOSE[14199][C-0000000f] app_stack.c: SIP/VOIPProvider-00000011 Internal Gosub(crm-hangup,s,1) complete GOSUB_RETVAL=
[2018-07-23 14:35:35] VERBOSE[1995][C-00000010] netsock2.c: Using SIP RTP TOS bits 184
[2018-07-23 14:35:35] VERBOSE[1995][C-00000010] netsock2.c: Using SIP RTP CoS mark 5
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [XXX5527XXX@from-trunk:1] NoOp("SIP/VOIPProvider-00000013", "Catch-All DID Match - Found XXX5527XXX - You probably want a DID for this.") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [XXX5527XXX@from-trunk:2] Log("SIP/VOIPProvider-00000013", "WARNING,Friendly Scanner from XXX.XXX.144.176") in new stack
[2018-07-23 14:35:35] WARNING[14452][C-00000010] Ext. XXX5527XXX: Friendly Scanner from XXX.XXX.144.176
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [XXX5527XXX@from-trunk:3] Set("SIP/VOIPProvider-00000013", "__FROM_DID=XXX5527XXX") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [XXX5527XXX@from-trunk:4] Goto("SIP/VOIPProvider-00000013", "ext-did,s,1") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx_builtins.c: Goto (ext-did,s,1)
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [s@ext-did:1] Set("SIP/VOIPProvider-00000013", "__DIRECTION=INBOUND") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [s@ext-did:2] Gosub("SIP/VOIPProvider-00000013", "sub-record-check,s,1(in,s,never)") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [s@sub-record-check:1] GotoIf("SIP/VOIPProvider-00000013", "0?initialized") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [s@sub-record-check:2] Set("SIP/VOIPProvider-00000013", "__REC_STATUS=INITIALIZED") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [s@sub-record-check:3] Set("SIP/VOIPProvider-00000013", "NOW=1532370935") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [s@sub-record-check:4] Set("SIP/VOIPProvider-00000013", "__DAY=23") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [s@sub-record-check:5] Set("SIP/VOIPProvider-00000013", "__MONTH=07") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [s@sub-record-check:6] Set("SIP/VOIPProvider-00000013", "__YEAR=2018") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [s@sub-record-check:7] Set("SIP/VOIPProvider-00000013", "__TIMESTR=20180723-143535") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [s@sub-record-check:8] Set("SIP/VOIPProvider-00000013", "__FROMEXTEN=unknown") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [s@sub-record-check:9] Set("SIP/VOIPProvider-00000013", "__MON_FMT=wav") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [s@sub-record-check:10] NoOp("SIP/VOIPProvider-00000013", "Recordings initialized") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [s@sub-record-check:11] ExecIf("SIP/VOIPProvider-00000013", "0?Set(ARG3=dontcare)") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [s@sub-record-check:12] Set("SIP/VOIPProvider-00000013", "REC_POLICY_MODE_SAVE=") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [s@sub-record-check:13] ExecIf("SIP/VOIPProvider-00000013", "0?Set(REC_STATUS=NO)") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [s@sub-record-check:14] GotoIf("SIP/VOIPProvider-00000013", "2?checkaction") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx_builtins.c: Goto (sub-record-check,s,17)
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [s@sub-record-check:17] GotoIf("SIP/VOIPProvider-00000013", "1?sub-record-check,in,1") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx_builtins.c: Goto (sub-record-check,in,1)
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [in@sub-record-check:1] NoOp("SIP/VOIPProvider-00000013", "Inbound Recording Check to s") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [in@sub-record-check:2] Set("SIP/VOIPProvider-00000013", "FROMEXTEN=unknown") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [in@sub-record-check:3] ExecIf("SIP/VOIPProvider-00000013", "10?Set(FROMEXTEN=XXX3422XXX)") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [in@sub-record-check:4] Gosub("SIP/VOIPProvider-00000013", "recordcheck,1(never,in,s)") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("SIP/VOIPProvider-00000013", "Starting recording check against never") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("SIP/VOIPProvider-00000013", "never") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx_builtins.c: Goto (sub-record-check,recordcheck,14)
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [recordcheck@sub-record-check:14] Set("SIP/VOIPProvider-00000013", "__REC_POLICY_MODE=NEVER") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [recordcheck@sub-record-check:15] Goto("SIP/VOIPProvider-00000013", "stoprec") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx_builtins.c: Goto (sub-record-check,recordcheck,25)
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [recordcheck@sub-record-check:25] NoOp("SIP/VOIPProvider-00000013", "Stopping recording: in, s") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [recordcheck@sub-record-check:26] Set("SIP/VOIPProvider-00000013", "__REC_STATUS=STOPPED") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [recordcheck@sub-record-check:27] System("SIP/VOIPProvider-00000013", "/var/lib/asterisk/bin/stoprecording.php "SIP/VOIPProvider-00000013"") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [recordcheck@sub-record-check:28] Return("SIP/VOIPProvider-00000013", "") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [in@sub-record-check:5] Return("SIP/VOIPProvider-00000013", "") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [s@ext-did:3] ExecIf("SIP/VOIPProvider-00000013", "0?Set(__FROM_DID=s)") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [s@ext-did:4] Set("SIP/VOIPProvider-00000013", "returnhere=1") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [s@ext-did:5] Gosub("SIP/VOIPProvider-00000013", "app-blacklist-check,s,1()") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [s@app-blacklist-check:1] GotoIf("SIP/VOIPProvider-00000013", "0?blacklisted") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [s@app-blacklist-check:2] Set("SIP/VOIPProvider-00000013", "CALLED_BLACKLIST=1") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [s@app-blacklist-check:3] Return("SIP/VOIPProvider-00000013", "") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [s@ext-did:6] Set("SIP/VOIPProvider-00000013", "CDR(did)=XXX5527XXX") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [s@ext-did:7] GotoIf("SIP/VOIPProvider-00000013", "0?") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [s@ext-did:8] ExecIf("SIP/VOIPProvider-00000013", "0 ?Set(CALLERID(name)=XXX3422XXX)") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [s@ext-did:9] Set("SIP/VOIPProvider-00000013", "__MOHCLASS=") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [s@ext-did:10] Set("SIP/VOIPProvider-00000013", "__REVERSAL_REJECT=FALSE") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [s@ext-did:11] GotoIf("SIP/VOIPProvider-00000013", "1?post-reverse-charge") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx_builtins.c: Goto (ext-did,s,13)
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [s@ext-did:13] NoOp("SIP/VOIPProvider-00000013", "") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [s@ext-did:14] Set("SIP/VOIPProvider-00000013", "__CALLINGNAMEPRES_SV=allowed_not_screened") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [s@ext-did:15] Set("SIP/VOIPProvider-00000013", "__CALLINGNUMPRES_SV=allowed_not_screened") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [s@ext-did:16] Set("SIP/VOIPProvider-00000013", "CALLERID(name-pres)=allowed_not_screened") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [s@ext-did:17] Set("SIP/VOIPProvider-00000013", "CALLERID(num-pres)=allowed_not_screened") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [s@ext-did:18] NoOp("SIP/VOIPProvider-00000013", "CallerID Entry Point") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [s@ext-did:19] Set("SIP/VOIPProvider-00000013", "__CRM_DIRECTION=INBOUND") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [s@ext-did:20] Set("SIP/VOIPProvider-00000013", "__CRM_SOURCE=XXX3422XXX") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [s@ext-did:21] Set("SIP/VOIPProvider-00000013", "__CRM_LINKEDID=1532370935.25") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [s@ext-did:22] ExecIf("SIP/VOIPProvider-00000013", "1?Set(CHANNEL(hangup_handler_push)=crm-hangup,s,1)") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [s@ext-did:23] Goto("SIP/VOIPProvider-00000013", "timeconditions,1,1") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx_builtins.c: Goto (timeconditions,1,1)
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [1@timeconditions:1] Set("SIP/VOIPProvider-00000013", "DB(TC/1/INUSESTATE)=INUSE") in new stack
[2018-07-23 14:35:35] VERBOSE[14452][C-00000010] pbx.c: Executing [1@timeconditions:2] Set("SIP/VOIPProvider-00000013", "DB(TC/1/NOT_INUSESTATE)=NOT_INUSE") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [1@timeconditions:3] NoOp("SIP/VOIPProvider-00000013", "TIMENOW: 14:35,Mon,23,Jul") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [1@timeconditions:4] NoOp("SIP/VOIPProvider-00000013", "TIMEMATCHED: FALSE") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [1@timeconditions:5] GotoIfTime("SIP/VOIPProvider-00000013", "08:00-09:00,mon-sun,*,*?truestate") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [1@timeconditions:6] GotoIf("SIP/VOIPProvider-00000013", "0?truegoto") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [1@timeconditions:7] ExecIf("SIP/VOIPProvider-00000013", "0?Set(DB(TC/1)=)") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [1@timeconditions:8] Set("SIP/VOIPProvider-00000013", "DEVICE_STATE(Custom:TC1)=INUSE") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [1@timeconditions:9] ExecIf("SIP/VOIPProvider-00000013", "0?Set(DEVICE_STATE(Custom:TCSTICKY)=INUSE)") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [1@timeconditions:10] GotoIf("SIP/VOIPProvider-00000013", "1?ext-miscdests,3,1") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx_builtins.c: Goto (ext-miscdests,3,1)
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [3@ext-miscdests:1] NoOp("SIP/VOIPProvider-00000013", "MiscDest: TestDest") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [3@ext-miscdests:2] Goto("SIP/VOIPProvider-00000013", "from-internal,9XXX6677XXX,1") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx_builtins.c: Goto (from-internal,9XXX6677XXX,1)
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [9XXX6677XXX@from-internal:1] Macro("SIP/VOIPProvider-00000013", "user-callerid,LIMIT,EXTERNAL,") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-user-callerid:1] Set("SIP/VOIPProvider-00000013", "TOUCH_MONITOR=1532370935.25") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-user-callerid:2] Set("SIP/VOIPProvider-00000013", "AMPUSER=XXX3422XXX") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-user-callerid:3] GotoIf("SIP/VOIPProvider-00000013", "0?report") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-user-callerid:4] ExecIf("SIP/VOIPProvider-00000013", "1?Set(REALCALLERIDNUM=XXX3422XXX)") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-user-callerid:5] Set("SIP/VOIPProvider-00000013", "AMPUSER=") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-user-callerid:6] GotoIf("SIP/VOIPProvider-00000013", "0?limit") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-user-callerid:7] Set("SIP/VOIPProvider-00000013", "AMPUSERCIDNAME=") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-user-callerid:8] ExecIf("SIP/VOIPProvider-00000013", "0?Set(__CIDMASQUERADING=TRUE)") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-user-callerid:9] GotoIf("SIP/VOIPProvider-00000013", "1?report") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx_builtins.c: Goto (macro-user-callerid,s,16)
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-user-callerid:16] NoOp("SIP/VOIPProvider-00000013", "Macro Depth is 1") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-user-callerid:17] GotoIf("SIP/VOIPProvider-00000013", "1?report2:macroerror") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx_builtins.c: Goto (macro-user-callerid,s,18)
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-user-callerid:18] GotoIf("SIP/VOIPProvider-00000013", "1?continue") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx_builtins.c: Goto (macro-user-callerid,s,37)
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-user-callerid:37] Set("SIP/VOIPProvider-00000013", "CALLERID(number)=XXX3422XXX") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-user-callerid:38] Set("SIP/VOIPProvider-00000013", "CALLERID(name)=XXX3422XXX") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-user-callerid:39] GotoIf("SIP/VOIPProvider-00000013", "0?cnum") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-user-callerid:40] Set("SIP/VOIPProvider-00000013", "CDR(cnam)=XXX3422XXX") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-user-callerid:41] Set("SIP/VOIPProvider-00000013", "CDR(cnum)=XXX3422XXX") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-user-callerid:42] Set("SIP/VOIPProvider-00000013", "CHANNEL(language)=en") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [9XXX6677XXX@from-internal:2] Gosub("SIP/VOIPProvider-00000013", "sub-record-check,s,1(out,9XXX6677XXX,dontcare)") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@sub-record-check:1] GotoIf("SIP/VOIPProvider-00000013", "10?initialized") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx_builtins.c: Goto (sub-record-check,s,10)
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@sub-record-check:10] NoOp("SIP/VOIPProvider-00000013", "Recordings initialized") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@sub-record-check:11] ExecIf("SIP/VOIPProvider-00000013", "0?Set(ARG3=dontcare)") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@sub-record-check:12] Set("SIP/VOIPProvider-00000013", "REC_POLICY_MODE_SAVE=NEVER") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@sub-record-check:13] ExecIf("SIP/VOIPProvider-00000013", "0?Set(REC_STATUS=NO)") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@sub-record-check:14] GotoIf("SIP/VOIPProvider-00000013", "3?checkaction") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx_builtins.c: Goto (sub-record-check,s,17)
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@sub-record-check:17] GotoIf("SIP/VOIPProvider-00000013", "1?sub-record-check,out,1") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx_builtins.c: Goto (sub-record-check,out,1)
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [out@sub-record-check:1] NoOp("SIP/VOIPProvider-00000013", "Outbound Recording Check from XXX3422XXX to 9XXX6677XXX") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [out@sub-record-check:2] Set("SIP/VOIPProvider-00000013", "RECMODE=") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [out@sub-record-check:3] ExecIf("SIP/VOIPProvider-00000013", "1?Goto(routewins)") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx_builtins.c: Goto (sub-record-check,out,7)
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [out@sub-record-check:7] Gosub("SIP/VOIPProvider-00000013", "recordcheck,1(dontcare,out,9XXX6677XXX)") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("SIP/VOIPProvider-00000013", "Starting recording check against dontcare") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("SIP/VOIPProvider-00000013", "dontcare") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [recordcheck@sub-record-check:3] Return("SIP/VOIPProvider-00000013", "") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [out@sub-record-check:8] Return("SIP/VOIPProvider-00000013", "") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [9XXX6677XXX@from-internal:3] ExecIf("SIP/VOIPProvider-00000013", "0 ?Set(CDR(accountcode)=)") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [9XXX6677XXX@from-internal:4] Set("SIP/VOIPProvider-00000013", "MOHCLASS=default") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [9XXX6677XXX@from-internal:5] Set("SIP/VOIPProvider-00000013", "_NODEST=") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [9XXX6677XXX@from-internal:6] Macro("SIP/VOIPProvider-00000013", "dialout-trunk,1,XXX6677XXX,,off") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-dialout-trunk:1] Set("SIP/VOIPProvider-00000013", "DIAL_TRUNK=1") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-dialout-trunk:2] ExecIf("SIP/VOIPProvider-00000013", "1?Set(DIAL_OPTIONS=tr)") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-dialout-trunk:3] GosubIf("SIP/VOIPProvider-00000013", "0?sub-pincheck,s,1()") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-dialout-trunk:4] GotoIf("SIP/VOIPProvider-00000013", "0?disabletrunk,1") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-dialout-trunk:5] Set("SIP/VOIPProvider-00000013", "DIAL_NUMBER=XXX6677XXX") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-dialout-trunk:6] Set("SIP/VOIPProvider-00000013", "DIAL_TRUNK_OPTIONS=tr") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-dialout-trunk:7] Set("SIP/VOIPProvider-00000013", "OUTBOUND_GROUP=OUT_1") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-dialout-trunk:8] Set("SIP/VOIPProvider-00000013", "DIAL_TRUNK_OPTIONS=T") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-dialout-trunk:9] GotoIf("SIP/VOIPProvider-00000013", "1?nomax") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx_builtins.c: Goto (macro-dialout-trunk,s,11)
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-dialout-trunk:11] GotoIf("SIP/VOIPProvider-00000013", "0?skipoutcid") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-dialout-trunk:12] Macro("SIP/VOIPProvider-00000013", "outbound-callerid,1") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-outbound-callerid:1] ExecIf("SIP/VOIPProvider-00000013", "1?Set(CALLERPRES(name-pres)=allowed_not_screened)") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-outbound-callerid:2] ExecIf("SIP/VOIPProvider-00000013", "1?Set(CALLERPRES(num-pres)=allowed_not_screened)") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-outbound-callerid:3] ExecIf("SIP/VOIPProvider-00000013", "0?Set(REALCALLERIDNUM=XXX3422XXX)") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-outbound-callerid:4] ExecIf("SIP/VOIPProvider-00000013", "0?Set(AMPUSER=XXX3422XXX)") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-outbound-callerid:5] GotoIf("SIP/VOIPProvider-00000013", "1?normcid") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx_builtins.c: Goto (macro-outbound-callerid,s,9)
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-outbound-callerid:9] Set("SIP/VOIPProvider-00000013", "USEROUTCID=") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-outbound-callerid:10] Set("SIP/VOIPProvider-00000013", "EMERGENCYCID=") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-outbound-callerid:11] Set("SIP/VOIPProvider-00000013", "TRUNKOUTCID=XXX5527XXX") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-outbound-callerid:12] GotoIf("SIP/VOIPProvider-00000013", "1?trunkcid") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx_builtins.c: Goto (macro-outbound-callerid,s,17)
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-outbound-callerid:17] ExecIf("SIP/VOIPProvider-00000013", "1?Set(CALLERID(all)=XXX5527XXX)") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-outbound-callerid:18] ExecIf("SIP/VOIPProvider-00000013", "0?Set(CALLERID(all)=)") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-outbound-callerid:19] ExecIf("SIP/VOIPProvider-00000013", "0?Set(CALLERID(all)=)") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-outbound-callerid:20] ExecIf("SIP/VOIPProvider-00000013", "0?Set(CALLERPRES(name-pres)=prohib_passed_screen)") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-outbound-callerid:21] ExecIf("SIP/VOIPProvider-00000013", "0?Set(CALLERPRES(num-pres)=prohib_passed_screen)") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-outbound-callerid:22] Set("SIP/VOIPProvider-00000013", "CDR(outbound_cnum)=XXX5527XXX") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-outbound-callerid:23] Set("SIP/VOIPProvider-00000013", "CDR(outbound_cnam)=") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-dialout-trunk:13] GosubIf("SIP/VOIPProvider-00000013", "1?sub-flp-1,s,1()") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@sub-flp-1:1] ExecIf("SIP/VOIPProvider-00000013", "0?Set(TARGET_FLP_1=056677400)") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@sub-flp-1:2] GotoIf("SIP/VOIPProvider-00000013", "0?match") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@sub-flp-1:3] ExecIf("SIP/VOIPProvider-00000013", "0?Set(TARGET_FLP_1=056677400)") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@sub-flp-1:4] GotoIf("SIP/VOIPProvider-00000013", "0?match") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@sub-flp-1:5] ExecIf("SIP/VOIPProvider-00000013", "0?Return()") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@sub-flp-1:6] ExecIf("SIP/VOIPProvider-00000013", "0?Return()") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@sub-flp-1:7] ExecIf("SIP/VOIPProvider-00000013", "0?Set(TARGET_FLP_1=056677400)") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@sub-flp-1:8] GotoIf("SIP/VOIPProvider-00000013", "0?match") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@sub-flp-1:9] ExecIf("SIP/VOIPProvider-00000013", "0?Set(TARGET_FLP_1=056677400)") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@sub-flp-1:10] GotoIf("SIP/VOIPProvider-00000013", "0?match") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@sub-flp-1:11] ExecIf("SIP/VOIPProvider-00000013", "0?Set(TARGET_FLP_1=56677400)") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@sub-flp-1:12] GotoIf("SIP/VOIPProvider-00000013", "0?match") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@sub-flp-1:13] Return("SIP/VOIPProvider-00000013", "") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-dialout-trunk:14] Set("SIP/VOIPProvider-00000013", "OUTNUM=XXX6677XXX") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-dialout-trunk:15] Set("SIP/VOIPProvider-00000013", "custom=SIP/VOIPProvider") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-dialout-trunk:16] ExecIf("SIP/VOIPProvider-00000013", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)T)") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-dialout-trunk:17] ExecIf("SIP/VOIPProvider-00000013", "0?Set(DIAL_TRUNK_OPTIONS=TM(confirm))") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-dialout-trunk:18] Macro("SIP/VOIPProvider-00000013", "dialout-trunk-predial-hook,") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("SIP/VOIPProvider-00000013", "") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-dialout-trunk:19] GotoIf("SIP/VOIPProvider-00000013", "1?skipcrm") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx_builtins.c: Goto (macro-dialout-trunk,s,25)
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-dialout-trunk:25] NoOp("SIP/VOIPProvider-00000013", "CRM Finished") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-dialout-trunk:26] GotoIf("SIP/VOIPProvider-00000013", "0?bypass,1") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-dialout-trunk:27] ExecIf("SIP/VOIPProvider-00000013", "0?Set(CONNECTEDLINE(num,i)=XXX6677XXX)") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-dialout-trunk:28] ExecIf("SIP/VOIPProvider-00000013", "0?Set(CONNECTEDLINE(name,i)=CID:XXX5527XXX)") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-dialout-trunk:29] ExecIf("SIP/VOIPProvider-00000013", "0?Set(CONNECTEDLINE(name,i)=CID:(Hidden)XXX5527XXX)") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-dialout-trunk:30] GotoIf("SIP/VOIPProvider-00000013", "0?customtrunk") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] pbx.c: Executing [s@macro-dialout-trunk:31] Dial("SIP/VOIPProvider-00000013", "SIP/VOIPProvider/XXX6677XXX,300,T") in new stack
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] netsock2.c: Using SIP RTP TOS bits 184
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] netsock2.c: Using SIP RTP CoS mark 5
[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] app_dial.c: Called SIP/VOIPProvider/XXX6677XXX
[2018-07-23 14:35:37] VERBOSE[14452][C-00000010] app_dial.c: SIP/VOIPProvider-00000014 answered SIP/VOIPProvider-00000013
[2018-07-23 14:35:37] VERBOSE[14457][C-00000010] bridge_channel.c: Channel SIP/VOIPProvider-00000014 joined 'simple_bridge' basic-bridge <b5409dc6-2b3e-41e7-90bc-f9b68fe2ceef>
[2018-07-23 14:35:37] VERBOSE[14452][C-00000010] bridge_channel.c: Channel SIP/VOIPProvider-00000013 joined 'simple_bridge' basic-bridge <b5409dc6-2b3e-41e7-90bc-f9b68fe2ceef>
6

After many hours of troubleshooting, still have this issue that when after hours and the call is sent to a Misc Dest or Ring Group, all you get is a ghost call and the number is not dialed. Any ideas of what might be happening?

I have the ring group as 91234567890# and the Misc Dest as 91234567890.

The logs were added to this post.

Thanks!

7

That’s not what your log lines show:

[2018-07-23 14:35:36] VERBOSE[14452][C-00000010] app_dial.c: Called SIP/VOIPProvider/XXX6677XXX
[2018-07-23 14:35:37] VERBOSE[14452][C-00000010] app_dial.c: SIP/VOIPProvider-00000014 answered SIP/VOIPProvider-00000013

According to the above, the call was dialed and the remote end answered.

8

Those are my troubleshooting skills, nonexistent.

So if the calls gets dialed, then why doesnt it ring on the receiving end?

The number I use for testing is my cell phone, and this one does not ring when this is executed, it might say it dialed it, and that my voip provider answered, but it never sent it to my phone?

I have tried also different cell provider numbers to no avail. This should seem so simple but its not.

9

Also contacted my VoIP provider and they dont see anything that can be blocking FW’ing calls.

The calls to these destinations do work from the regular extensions, just not from the Destination No-Match.

10

Could it be a NAT problem?

11

I’m guessing that you have two problems. The log shows the outbound call ‘answered’ only one second after it was initiated, but setup time to a cell phone takes several seconds. I believe that the provider routed the call to an error announcement. The second issue is that the caller did not hear the announcement.

If an on-site PBX is behind a NAT, most calls will work without forwarding the RTP port range, because when audio is sent to the trunk (from an extension, IVR prompt, voicemail greeting, etc.), audio coming from the trunk looks like ‘replies’, so the firewall passes it to the PBX. However, trunk-to-trunk connections will fail, because audio from both trunks is blocked by the firewall. As a test, use a Ring Group and change the Play Music On Hold option from Ring to default. The caller will now hear music while the call is forwarded and with luck you’ll then hear the error announcement.

The other issue is related to caller ID. By default, forwarded calls attempt to display the number of the original caller on the forwarded-to phone. Some providers don’t allow you to send a caller ID that’s not yours. If that’s your situation, you can either use a different provider for forwarded calls, or set the system to send your main company number instead. Some other providers do permit sending an arbitrary caller ID, but have special header requirements such as Diversion or P-Asserted-Identity, in which case you likely need to adjust your trunk settings accordingly. As a test, try setting Outbound CallerID for the outgoing trunk to your main number (in the proper format) and setting CID Options to Force Trunk CID. With luck, the forwarded-to cell phone will ring and show the main company number. If that works, set CID Options back to normal and fix the trunk settings.

12

Stewart, your advising of forcing the CallerID worked like a charm. Once I fixed all that on the Trunk side, the calls were at least going out and reaching the callee.

Once that was taken care of, I was having issues with voice, as none of the parties would hear each other (caller, callee). So I stumbled upon another post from back when, and they recommended going inside the Asterisk Sip Settings and going inside the Sip Settings and in the RTP Keep Alive Option make it a 1 (default is 0). After I did this the calls were able to establish audio and it’s been working great so far. This made sense to test as the RTP does deal with voice.

My FW so far is not forwarding any ports, as I rather keep people from trying to hack us thru those ports.

Thank you so much for taking the time on this.

Best!

13

I have this problem with “one-armed” calls (calls coming from my provider and going back to through that provider). My “ham-fisted” solution is to set up a second “emergency” outbound route through another provider. I use a pre-paid “outbound only” provider for this. For the dozens of minutes I use every year, the $20 I put in back in 2015 is still being whittled away.

14

Something to consider, thanks for the heads up!

15

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