Cannot make outbound call 401 Unauthorized

xanmanza · September 26, 2015, 3:41pm

Hey guys

Just wanted some help on setting up my first PBX.
My setup is as follows:
Elastix Server running on VirtualBox. (10.0.0.155)
Zoiper phone running on Windows. (10.0.0.150)

This is the content of my error log when trying to make an outbound call from the Zoiper phone:

[2015-09-26 13:27:44] VERBOSE[19363] chan_sip.c: Reliably Transmitting (no NAT) to 10.0.0.150:62743:
OPTIONS sip:23@10.0.0.150:62743;rinstance=203a04d13151b8ca;transport=UDP SIP/2.0^M
Via: SIP/2.0/UDP 10.0.0.155:5060;branch=z9hG4bK1a5642f1^M
Max-Forwards: 70^M
From: “Unknown” sip:Unknown@10.0.0.155;tag=as06fe8732^M
To: sip:23@10.0.0.150:62743;rinstance=203a04d13151b8ca;transport=UDP^M
Contact: sip:Unknown@10.0.0.155:5060^M
Call-ID: 33100bd4622e740632afc91f26853715@10.0.0.155:5060^M
CSeq: 102 OPTIONS^M
User-Agent: FPBX-2.11.0(11.17.1)^M
Date: Sat, 26 Sep 2015 15:27:44 GMT^M
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE^M
Supported: replaces, timer^M
Content-Length: 0^M
^M

[2015-09-26 13:27:44] VERBOSE[19363] chan_sip.c:
<— SIP read from UDP:10.0.0.150:62743 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.0.0.155:5060;branch=z9hG4bK1a5642f1
Contact: sip:10.0.0.150:62743
To: sip:23@10.0.0.150:62743;rinstance=203a04d13151b8ca;transport=UDP;tag=cd14631b
From: “Unknown” sip:Unknown@10.0.0.155;tag=as06fe8732
Call-ID: 33100bd4622e740632afc91f26853715@10.0.0.155:5060
CSeq: 102 OPTIONS
Accept: application/sdp, application/sdp
Accept-Language: en
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE
Supported: replaces, norefersub, extended-refer, timer, outbound, path, X-cisco-serviceuri
User-Agent: Z 3.9.32144 r32121
Allow-Events: presence, kpml
Content-Length: 0

<------------->
[2015-09-26 13:27:44] VERBOSE[19363] chan_sip.c: — (14 headers 0 lines) —
[2015-09-26 13:27:44] VERBOSE[19363] chan_sip.c: Really destroying SIP dialog ‘33100bd4622e740632afc91f26853715@10.0.0.155:5060’ Method: OPTIONS
[2015-09-26 13:28:44] VERBOSE[19363] chan_sip.c: Reliably Transmitting (no NAT) to 10.0.0.150:62743:
OPTIONS sip:23@10.0.0.150:62743;rinstance=203a04d13151b8ca;transport=UDP SIP/2.0^M
Via: SIP/2.0/UDP 10.0.0.155:5060;branch=z9hG4bK476a4ef0^M
Max-Forwards: 70^M
From: “Unknown” sip:Unknown@10.0.0.155;tag=as73a32c97^M
To: sip:23@10.0.0.150:62743;rinstance=203a04d13151b8ca;transport=UDP^M
Contact: sip:Unknown@10.0.0.155:5060^M
Call-ID: 242e34396b31a53a6a5e796d2bd1d170@10.0.0.155:5060^M
CSeq: 102 OPTIONS^M
User-Agent: FPBX-2.11.0(11.17.1)^M
Date: Sat, 26 Sep 2015 15:28:44 GMT^M
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE^M
Supported: replaces, timer^M
Content-Length: 0^M
^M

[2015-09-26 13:28:44] VERBOSE[19363] chan_sip.c:
<— SIP read from UDP:10.0.0.150:62743 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.0.0.155:5060;branch=z9hG4bK476a4ef0
Contact: sip:10.0.0.150:62743
To: sip:23@10.0.0.150:62743;rinstance=203a04d13151b8ca;transport=UDP;tag=1005000a
From: “Unknown” sip:Unknown@10.0.0.155;tag=as73a32c97
Call-ID: 242e34396b31a53a6a5e796d2bd1d170@10.0.0.155:5060
CSeq: 102 OPTIONS
Accept: application/sdp, application/sdp
Accept-Language: en
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE
Supported: replaces, norefersub, extended-refer, timer, outbound, path, X-cisco-serviceuri
User-Agent: Z 3.9.32144 r32121
Allow-Events: presence, kpml
Content-Length: 0

<------------->
[2015-09-26 13:28:44] VERBOSE[19363] chan_sip.c: — (14 headers 0 lines) —
[2015-09-26 13:28:44] VERBOSE[19363] chan_sip.c: Really destroying SIP dialog ‘242e34396b31a53a6a5e796d2bd1d170@10.0.0.155:5060’ Method: OPTIONS
[2015-09-26 13:29:17] VERBOSE[19363] chan_sip.c:
<— SIP read from UDP:10.0.0.150:62743 —>
INVITE sip:00123480502@10.0.0.155;transport=UDP SIP/2.0
Via: SIP/2.0/UDP 10.0.0.150:62743;branch=z9hG4bK-524287-1—228e929fae8fb4a9
Max-Forwards: 70
Contact: sip:23@10.0.0.150:62743;transport=UDP
To: sip:00123480502@10.0.0.155;transport=UDP
From: "23"sip:23@10.0.0.155;transport=UDP;tag=43233329
Call-ID: e39DOKoqJV5w1qqsu6O0pw…
CSeq: 1 INVITE
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE
Content-Type: application/sdp
Supported: replaces, norefersub, extended-refer, timer, outbound, path, X-cisco-serviceuri
User-Agent: Z 3.9.32144 r32121
Allow-Events: presence, kpml
Content-Length: 161

v=0
o=Z 0 0 IN IP4 10.0.0.150
s=Z
c=IN IP4 10.0.0.150
t=0 0
m=audio 8000 RTP/AVP 3 8 0 101
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=sendrecv
<------------->
[2015-09-26 13:29:17] VERBOSE[19363] chan_sip.c: — (14 headers 9 lines) —
[2015-09-26 13:29:17] VERBOSE[19363] chan_sip.c: Sending to 10.0.0.150:62743 (no NAT)
[2015-09-26 13:29:17] VERBOSE[19363][C-0000000c] chan_sip.c: Sending to 10.0.0.150:62743 (no NAT)
[2015-09-26 13:29:17] VERBOSE[19363][C-0000000c] chan_sip.c: Using INVITE request as basis request - e39DOKoqJV5w1qqsu6O0pw…
[2015-09-26 13:29:17] VERBOSE[19363][C-0000000c] chan_sip.c: Found peer ‘23’ for ‘23’ from 10.0.0.150:62743
[2015-09-26 13:29:17] VERBOSE[19363][C-0000000c] chan_sip.c:
<— Reliably Transmitting (no NAT) to 10.0.0.150:62743 —>
SIP/2.0 401 Unauthorized^M
Via: SIP/2.0/UDP 10.0.0.150:62743;branch=z9hG4bK-524287-1—228e929fae8fb4a9;received=10.0.0.150^M
From: "23"sip:23@10.0.0.155;transport=UDP;tag=43233329^M
To: sip:00123480502@10.0.0.155;transport=UDP;tag=as1115e279^M
Call-ID: e39DOKoqJV5w1qqsu6O0pw…^M
CSeq: 1 INVITE^M
Server: FPBX-2.11.0(11.17.1)^M
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE^M
Supported: replaces, timer^M
WWW-Authenticate: Digest algorithm=MD5, realm=“asterisk”, nonce=“74aff174”^M
Content-Length: 0^M
^M
<------------>
[2015-09-26 13:29:17] VERBOSE[19363][C-0000000c] chan_sip.c: Scheduling destruction of SIP dialog ‘e39DOKoqJV5w1qqsu6O0pw…’ in 6400 ms (Method: INVITE)
[2015-09-26 13:29:17] VERBOSE[19363] chan_sip.c:
<— SIP read from UDP:10.0.0.150:62743 —>
PUBLISH sip:23@10.0.0.155;transport=UDP SIP/2.0
Via: SIP/2.0/UDP 10.0.0.150:62743;branch=z9hG4bK-524287-1—f081e64c3695f709
Max-Forwards: 70
Contact: sip:23@10.0.0.150:62743;transport=UDP
To: "23"sip:23@10.0.0.155;transport=UDP
From: "23"sip:23@10.0.0.155;transport=UDP;tag=0f388025
Call-ID: Fq9Ar_ijmfIYsqRZy6EMag…
CSeq: 1 PUBLISH
Expires: 600
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE
Content-Type: application/pidf+xml
Supported: replaces, norefersub, extended-refer, timer, outbound, path, X-cisco-serviceuri
User-Agent: Z 3.9.32144 r32121
Event: presence
Allow-Events: presence, kpml
Content-Length: 260
<?xml version="1.0" encoding="UTF-8"?>
open On the phone

<------------->
[2015-09-26 13:29:17] VERBOSE[19363] chan_sip.c: — (16 headers 3 lines) —
[2015-09-26 13:29:17] VERBOSE[19363] chan_sip.c: Sending to 10.0.0.150:62743 (no NAT)
[2015-09-26 13:29:17] VERBOSE[19363] chan_sip.c:
<— Transmitting (no NAT) to 10.0.0.150:62743 —>
SIP/2.0 489 Bad Event^M
Via: SIP/2.0/UDP 10.0.0.150:62743;branch=z9hG4bK-524287-1—f081e64c3695f709;received=10.0.0.150^M
From: "23"sip:23@10.0.0.155;transport=UDP;tag=0f388025^M
To: "23"sip:23@10.0.0.155;transport=UDP;tag=as33930d9b^M
Call-ID: Fq9Ar_ijmfIYsqRZy6EMag…^M
CSeq: 1 PUBLISH^M
Server: FPBX-2.11.0(11.17.1)^M
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE^M
Supported: replaces, timer^M
Content-Length: 0^M
^M

<------------>
[2015-09-26 13:29:17] VERBOSE[19363] chan_sip.c: Really destroying SIP dialog ‘Fq9Ar_ijmfIYsqRZy6EMag…’ Method: PUBLISH
[2015-09-26 13:29:17] VERBOSE[19363] chan_sip.c:
<— SIP read from UDP:10.0.0.150:62743 —>
SUBSCRIBE sip:23@10.0.0.155;transport=UDP SIP/2.0
Via: SIP/2.0/UDP 10.0.0.150:62743;branch=z9hG4bK-524287-1—054fc99895a4a94f
Max-Forwards: 70
Contact: sip:23@10.0.0.150:62743;transport=UDP
To: "23"sip:23@10.0.0.155;transport=UDP
From: "23"sip:23@10.0.0.155;transport=UDP;tag=c33b6a00
Call-ID: BnE1d3Bl0y-f2y-SolaB9g…
CSeq: 1 SUBSCRIBE
Expires: 600
Accept: application/watcherinfo+xml
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE
Supported: replaces, norefersub, extended-refer, timer, outbound, path, X-cisco-serviceuri
User-Agent: Z 3.9.32144 r32121
Event: presence.winfo
Allow-Events: presence, kpml
Content-Length: 0

<------------->
[2015-09-26 13:29:17] VERBOSE[19363] chan_sip.c: — (16 headers 0 lines) —
[2015-09-26 13:29:17] VERBOSE[19363] chan_sip.c: Sending to 10.0.0.150:62743 (no NAT)
[2015-09-26 13:29:17] VERBOSE[19363] chan_sip.c: Creating new subscription
[2015-09-26 13:29:17] VERBOSE[19363] chan_sip.c: Sending to 10.0.0.150:62743 (no NAT)
[2015-09-26 13:29:17] VERBOSE[19363] chan_sip.c: list_route: hop: sip:23@10.0.0.150:62743;transport=UDP
[2015-09-26 13:29:17] VERBOSE[19363] chan_sip.c: Found peer ‘23’ for ‘23’ from 10.0.0.150:62743
[2015-09-26 13:29:17] VERBOSE[19363] chan_sip.c:
<— Transmitting (no NAT) to 10.0.0.150:62743 —>
SIP/2.0 401 Unauthorized^M
Via: SIP/2.0/UDP 10.0.0.150:62743;branch=z9hG4bK-524287-1—054fc99895a4a94f;received=10.0.0.150^M
From: "23"sip:23@10.0.0.155;transport=UDP;tag=c33b6a00^M
To: "23"sip:23@10.0.0.155;transport=UDP;tag=as7d689ff8^M
Call-ID: BnE1d3Bl0y-f2y-SolaB9g…^M
CSeq: 1 SUBSCRIBE^M
Server: FPBX-2.11.0(11.17.1)^M
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE^M
Supported: replaces, timer^M
WWW-Authenticate: Digest algorithm=MD5, realm=“asterisk”, nonce=“01b32925”^M
Content-Length: 0^M
^M

<------------>
[2015-09-26 13:29:17] VERBOSE[19363] chan_sip.c: Scheduling destruction of SIP dialog ‘BnE1d3Bl0y-f2y-SolaB9g…’ in 6400 ms (Method: SUBSCRIBE)
[2015-09-26 13:29:17] VERBOSE[19363] chan_sip.c:
<— SIP read from UDP:10.0.0.150:62743 —>
ACK sip:00123480502@10.0.0.155;transport=UDP SIP/2.0
Via: SIP/2.0/UDP 10.0.0.150:62743;branch=z9hG4bK-524287-1—228e929fae8fb4a9
Max-Forwards: 70
To: sip:00123480502@10.0.0.155;transport=UDP;tag=as1115e279
From: "23"sip:23@10.0.0.155;transport=UDP;tag=43233329
Call-ID: e39DOKoqJV5w1qqsu6O0pw…
CSeq: 1 ACK
Content-Length: 0

<------------->
[2015-09-26 13:29:17] VERBOSE[19363] chan_sip.c: — (8 headers 0 lines) —
[2015-09-26 13:29:17] VERBOSE[19363] chan_sip.c:
<— SIP read from UDP:10.0.0.150:62743 —>
INVITE sip:00123480502@10.0.0.155;transport=UDP SIP/2.0
Via: SIP/2.0/UDP 10.0.0.150:62743;branch=z9hG4bK-524287-1—a88cd24125cfa082
Max-Forwards: 70
Contact: sip:23@10.0.0.150:62743;transport=UDP
To: sip:00123480502@10.0.0.155;transport=UDP
From: “23"sip:23@10.0.0.155;transport=UDP;tag=43233329
Call-ID: e39DOKoqJV5w1qqsu6O0pw…
CSeq: 2 INVITE
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE
Content-Type: application/sdp
Supported: replaces, norefersub, extended-refer, timer, outbound, path, X-cisco-serviceuri
User-Agent: Z 3.9.32144 r32121
Authorization: Digest username=“23”,realm=“asterisk”,nonce=“74aff174”,uri="sip:00123480502@10.0.0.155;transport=UDP”,response=“c8e691a00284d1bb4d5c1b20bd2e5604”,algorithm=MD5
Allow-Events: presence, kpml
Content-Length: 161

v=0
o=Z 0 0 IN IP4 10.0.0.150
s=Z
c=IN IP4 10.0.0.150
t=0 0
m=audio 8000 RTP/AVP 3 8 0 101
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=sendrecv
<------------->
[2015-09-26 13:29:17] VERBOSE[19363] chan_sip.c: — (15 headers 9 lines) —
[2015-09-26 13:29:17] VERBOSE[19363][C-0000000c] chan_sip.c: Sending to 10.0.0.150:62743 (no NAT)
[2015-09-26 13:29:17] VERBOSE[19363][C-0000000c] chan_sip.c: Using INVITE request as basis request - e39DOKoqJV5w1qqsu6O0pw…
[2015-09-26 13:29:17] VERBOSE[19363][C-0000000c] chan_sip.c: Found peer ‘23’ for ‘23’ from 10.0.0.150:62743
[2015-09-26 13:29:17] VERBOSE[19363][C-0000000c] chan_sip.c: Found RTP audio format 3
[2015-09-26 13:29:17] VERBOSE[19363][C-0000000c] chan_sip.c: Found RTP audio format 8
[2015-09-26 13:29:17] VERBOSE[19363][C-0000000c] chan_sip.c: Found RTP audio format 0
[2015-09-26 13:29:17] VERBOSE[19363][C-0000000c] chan_sip.c: Found RTP audio format 101
[2015-09-26 13:29:17] VERBOSE[19363][C-0000000c] chan_sip.c: Found audio description format telephone-event for ID 101
[2015-09-26 13:29:17] VERBOSE[19363][C-0000000c] chan_sip.c: Capabilities: us - (gsm|ulaw|alaw), peer - audio=(gsm|ulaw|alaw)/video=(nothing)/text=(nothing), combined - (gsm|ulaw|alaw)
[2015-09-26 13:29:17] VERBOSE[19363][C-0000000c] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|)
[2015-09-26 13:29:17] VERBOSE[19363][C-0000000c] chan_sip.c: Peer audio RTP is at port 10.0.0.150:8000
[2015-09-26 13:29:17] VERBOSE[19363][C-0000000c] chan_sip.c: Looking for 00123480502 in from-internal (domain 10.0.0.155)
[2015-09-26 13:29:17] VERBOSE[19363][C-0000000c] chan_sip.c: list_route: hop: sip:23@10.0.0.150:62743;transport=UDP
[2015-09-26 13:29:17] VERBOSE[19363][C-0000000c] chan_sip.c:
<— Transmitting (no NAT) to 10.0.0.150:62743 —>
SIP/2.0 100 Trying^M
Via: SIP/2.0/UDP 10.0.0.150:62743;branch=z9hG4bK-524287-1—a88cd24125cfa082;received=10.0.0.150^M
From: "23"sip:23@10.0.0.155;transport=UDP;tag=43233329^M
To: sip:00123480502@10.0.0.155;transport=UDP^M
Call-ID: e39DOKoqJV5w1qqsu6O0pw…^M
CSeq: 2 INVITE^M
Server: FPBX-2.11.0(11.17.1)^M
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE^M
Supported: replaces, timer^M
Session-Expires: 1800;refresher=uas^M
Contact: sip:00123480502@10.0.0.155:5060^M
Content-Length: 0^M
^M

<------------>
[2015-09-26 13:29:17] VERBOSE[22504][C-0000000c] chan_sip.c: Audio is at 13048
[2015-09-26 13:29:17] VERBOSE[22504][C-0000000c] chan_sip.c: Adding codec 100004 (alaw) to SDP
[2015-09-26 13:29:17] VERBOSE[22504][C-0000000c] chan_sip.c: Adding codec 100002 (gsm) to SDP
[2015-09-26 13:29:17] VERBOSE[22504][C-0000000c] chan_sip.c: Adding codec 100003 (ulaw) to SDP
[2015-09-26 13:29:17] VERBOSE[22504][C-0000000c] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP
[2015-09-26 13:29:17] VERBOSE[22504][C-0000000c] chan_sip.c:
<— Transmitting (no NAT) to 10.0.0.150:62743 —>
SIP/2.0 183 Session Progress^M
Via: SIP/2.0/UDP 10.0.0.150:62743;branch=z9hG4bK-524287-1—a88cd24125cfa082;received=10.0.0.150^M
From: "23"sip:23@10.0.0.155;transport=UDP;tag=43233329^M
To: sip:00123480502@10.0.0.155;transport=UDP;tag=as62b97018^M
Call-ID: e39DOKoqJV5w1qqsu6O0pw…^M
CSeq: 2 INVITE^M
Server: FPBX-2.11.0(11.17.1)^M
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE^M
Supported: replaces, timer^M
Session-Expires: 1800;refresher=uas^M
Contact: sip:00123480502@10.0.0.155:5060^M
Content-Type: application/sdp^M
Require: timer^M
Content-Length: 279^M
^M
v=0^M
o=root 2071929838 2071929838 IN IP4 10.0.0.155^M
s=Asterisk PBX 11.17.1^M
c=IN IP4 10.0.0.155^M
t=0 0^M
m=audio 13048 RTP/AVP 8 3 0 101^M
a=rtpmap:8 PCMA/8000^M
a=rtpmap:3 GSM/8000^M
a=rtpmap:0 PCMU/8000^M
a=rtpmap:101 telephone-event/8000^M
a=fmtp:101 0-16^M
a=ptime:20^M
a=sendrecv^M

<------------>
[2015-09-26 13:29:17] VERBOSE[19363] chan_sip.c:
<— SIP read from UDP:10.0.0.150:62743 —>
SUBSCRIBE sip:23@10.0.0.155;transport=UDP SIP/2.0
Via: SIP/2.0/UDP 10.0.0.150:62743;branch=z9hG4bK-524287-1—1d473c681ac1415a
Max-Forwards: 70
Contact: sip:23@10.0.0.150:62743;transport=UDP
To: "23"sip:23@10.0.0.155;transport=UDP
From: “23"sip:23@10.0.0.155;transport=UDP;tag=c33b6a00
Call-ID: BnE1d3Bl0y-f2y-SolaB9g…
CSeq: 2 SUBSCRIBE
Expires: 600
Accept: application/watcherinfo+xml
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE
Supported: replaces, norefersub, extended-refer, timer, outbound, path, X-cisco-serviceuri
User-Agent: Z 3.9.32144 r32121
Authorization: Digest username=“23”,realm=“asterisk”,nonce=“01b32925”,uri="sip:23@10.0.0.155;transport=UDP”,response=“1b488205395c5e1e48dffba8977e951e”,algorithm=MD5
Event: presence.winfo
Allow-Events: presence, kpml
Content-Length: 0

<------------->
[2015-09-26 13:29:17] VERBOSE[19363] chan_sip.c: — (17 headers 0 lines) —
[2015-09-26 13:29:17] VERBOSE[19363] chan_sip.c: Creating new subscription
[2015-09-26 13:29:17] VERBOSE[19363] chan_sip.c: Sending to 10.0.0.150:62743 (no NAT)
[2015-09-26 13:29:17] VERBOSE[19363] chan_sip.c: Found peer ‘23’ for ‘23’ from 10.0.0.150:62743
[2015-09-26 13:29:17] VERBOSE[19363] chan_sip.c:
<— Transmitting (no NAT) to 10.0.0.150:62743 —>
SIP/2.0 489 Bad Event^M
Via: SIP/2.0/UDP 10.0.0.150:62743;branch=z9hG4bK-524287-1—1d473c681ac1415a;received=10.0.0.150^M
From: "23"sip:23@10.0.0.155;transport=UDP;tag=c33b6a00^M
To: "23"sip:23@10.0.0.155;transport=UDP;tag=as7d689ff8^M
Call-ID: BnE1d3Bl0y-f2y-SolaB9g…^M
CSeq: 2 SUBSCRIBE^M
Server: FPBX-2.11.0(11.17.1)^M
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE^M
Supported: replaces, timer^M
Content-Length: 0^M
^M
<------------>
[2015-09-26 13:29:17] VERBOSE[19363] chan_sip.c: Really destroying SIP dialog ‘BnE1d3Bl0y-f2y-SolaB9g…’ Method: SUBSCRIBE
[2015-09-26 13:29:25] VERBOSE[22504][C-0000000c] chan_sip.c:
<— Reliably Transmitting (no NAT) to 10.0.0.150:62743 —>
SIP/2.0 503 Service Unavailable^M
Via: SIP/2.0/UDP 10.0.0.150:62743;branch=z9hG4bK-524287-1—a88cd24125cfa082;received=10.0.0.150^M
From: "23"sip:23@10.0.0.155;transport=UDP;tag=43233329^M
To: sip:00123480502@10.0.0.155;transport=UDP;tag=as62b97018^M
Call-ID: e39DOKoqJV5w1qqsu6O0pw…^M
CSeq: 2 INVITE^M
Server: FPBX-2.11.0(11.17.1)^M
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE^M
Supported: replaces, timer^M
Session-Expires: 1800;refresher=uas^M
Content-Length: 0^M
^M

<------------>
[2015-09-26 13:29:25] WARNING[22504][C-0000000c] channel.c: Prodding channel ‘SIP/23-0000000c’ failed
[2015-09-26 13:29:25] VERBOSE[19363] chan_sip.c:
<— SIP read from UDP:10.0.0.150:62743 —>
ACK sip:00123480502@10.0.0.155;transport=UDP SIP/2.0
Via: SIP/2.0/UDP 10.0.0.150:62743;branch=z9hG4bK-524287-1—a88cd24125cfa082
Max-Forwards: 70
To: sip:00123480502@10.0.0.155;transport=UDP;tag=as62b97018
From: "23"sip:23@10.0.0.155;transport=UDP;tag=43233329
Call-ID: e39DOKoqJV5w1qqsu6O0pw…
CSeq: 2 ACK
Content-Length: 0

<------------->
[2015-09-26 13:29:25] VERBOSE[19363] chan_sip.c: — (8 headers 0 lines) —
[2015-09-26 13:29:25] VERBOSE[19363] chan_sip.c: Really destroying SIP dialog ‘e39DOKoqJV5w1qqsu6O0pw…’ Method: ACK
[2015-09-26 13:29:25] VERBOSE[19363] chan_sip.c:
<— SIP read from UDP:10.0.0.150:62743 —>
PUBLISH sip:23@10.0.0.155;transport=UDP SIP/2.0
Via: SIP/2.0/UDP 10.0.0.150:62743;branch=z9hG4bK-524287-1—e0882e80fc83748e
Max-Forwards: 70
Contact: sip:23@10.0.0.150:62743;transport=UDP
To: "23"sip:23@10.0.0.155;transport=UDP
From: "23"sip:23@10.0.0.155;transport=UDP;tag=c577ed5a
Call-ID: 8djR5CHuvPvpOL1lCtV13A…
CSeq: 1 PUBLISH
Expires: 600
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE
Content-Type: application/pidf+xml
Supported: replaces, norefersub, extended-refer, timer, outbound, path, X-cisco-serviceuri
User-Agent: Z 3.9.32144 r32121
Event: presence
Allow-Events: presence, kpml
Content-Length: 254
<?xml version="1.0" encoding="UTF-8"?>
open Online

<------------->
[2015-09-26 13:29:25] VERBOSE[19363] chan_sip.c: — (16 headers 3 lines) —
[2015-09-26 13:29:25] VERBOSE[19363] chan_sip.c: Sending to 10.0.0.150:62743 (no NAT)
[2015-09-26 13:29:25] VERBOSE[19363] chan_sip.c:

Sorry for the long debug output, I’m assuming every bit of info is important.
I can do commands like *60 successfully so I am assuming the phone is correctly registered, but I cannot make outbound calls.
Please advise if possible and also advise on ways I could better provide debug output I am very new to this whole world

david55 · September 28, 2015, 2:07pm

The 401 is not a problem. The question is why are you getting service unavailable. You don’t have sufficient logging to answer that. Try again with verbosity set to 5 and possibly with debug set to 5.

xanmanza · September 28, 2015, 5:01pm

Hi David.

Thanks for your reply.
Here is my output after changing verbose and debug settings:

<— SIP read from UDP:10.0.0.150:50372 —>
INVITE sip:00123480502@10.0.0.155;transport=UDP SIP/2.0
Via: SIP/2.0/UDP 10.0.0.150:50372;branch=z9hG4bK-524287-1—22fd7c1c0d5fbe6f
Max-Forwards: 70
Contact: sip:23@10.0.0.150:50372;transport=UDP
To: sip:00123480502@10.0.0.155;transport=UDP
From: "23"sip:23@10.0.0.155;transport=UDP;tag=ce571443
Call-ID: zoLzYsUXWfaZYrFG-td34A…
CSeq: 1 INVITE
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIB E
Content-Type: application/sdp
Supported: replaces, norefersub, extended-refer, timer, outbound, path, X-cisco- serviceuri
User-Agent: Z 3.9.32144 r32121
Allow-Events: presence, kpml
Content-Length: 161

v=0
o=Z 0 0 IN IP4 10.0.0.150
s=Z
c=IN IP4 10.0.0.150
t=0 0
m=audio 8000 RTP/AVP 3 8 0 101
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=sendrecv
<------------->
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 0 [ 5 [2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 1 [ 7 [2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 2 [ 1 [2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 3 [ 4 [2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 4 [ 4 [2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 5 [ 5 [2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 6 [ 3 [2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 7 [ 1 [2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 8 [ 8 [2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 9 [ 2 [2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 10 [ 9 [2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 11 [ 3 [2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 12 [ 2 [2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 13 [ 1 [2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 14 [ [2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Body 0 [ [2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Body 1 [ 2 [2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Body 2 [ [2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Body 3 [ 1 [2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Body 4 [ [2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Body 5 [ 3 [2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Body 6 [ 3 [2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Body 7 [ 1 [2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9543 parse_request: Body 8 [ 1 — (14 headers 9 lines) —
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9055 find_call: = Looking for Cal [2015-09-28 14:43:35] DEBUG[2600]: acl.c:979 ast_ouraddrfor: For destination ‘10 [2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:3881 ast_sip_ouraddrfor: Setting S [2015-09-28 14:43:35] DEBUG[2600]: netsock2.c:138 ast_sockaddr_split_hostport: S [2015-09-28 14:43:35] DEBUG[2600]: netsock2.c:192 ast_sockaddr_split_hostport: . Sending to 10.0.0.150:50372 (no NAT)
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:8658 sip_alloc: Allocating new SIP [2015-09-28 14:43:35] DEBUG[2600][C-00000000]: chan_sip.c:28459 handle_incoming: [2015-09-28 14:43:35] DEBUG[2600][C-00000000]: sip/reqresp_parser.c:1603 parse_s [2015-09-28 14:43:35] DEBUG[2600][C-00000000]: sip/reqresp_parser.c:1618 parse_s [2015-09-28 14:43:35] DEBUG[2600][C-00000000]: sip/reqresp_parser.c:1626 parse_s [2015-09-28 14:43:35] DEBUG[2600][C-00000000]: sip/reqresp_parser.c:1618 parse_s [2015-09-28 14:43:35] DEBUG[2600][C-00000000]: sip/reqresp_parser.c:1626 parse_s [2015-09-28 14:43:35] DEBUG[2600][C-00000000]: sip/reqresp_parser.c:1618 parse_s [2015-09-28 14:43:35] DEBUG[2600][C-00000000]: sip/reqresp_parser.c:1654 parse_s [2015-09-28 14:43:35] DEBUG[2600][C-00000000]: sip/reqresp_parser.c:1618 parse_s [2015-09-28 14:43:35] DEBUG[2600][C-00000000]: sip/reqresp_parser.c:1626 parse_s [2015-09-28 14:43:35] DEBUG[2600][C-00000000]: sip/reqresp_parser.c:1618 parse_s [2015-09-28 14:43:35] DEBUG[2600][C-00000000]: sip/reqresp_parser.c:1626 parse_s [2015-09-28 14:43:35] DEBUG[2600][C-00000000]: sip/reqresp_parser.c:1618 parse_s [2015-09-28 14:43:35] DEBUG[2600][C-00000000]: sip/reqresp_parser.c:1626 parse_s [2015-09-28 14:43:35] DEBUG[2600][C-00000000]: sip/reqresp_parser.c:1618 parse_s [2015-09-28 14:43:35] DEBUG[2600][C-00000000]: sip/reqresp_parser.c:1652 parse_s [2015-09-28 14:43:35] DEBUG[2600][C-00000000]: netsock2.c:138 ast_sockaddr_split [2015-09-28 14:43:35] DEBUG[2600][C-00000000]: netsock2.c:192 ast_sockaddr_split Sending to 10.0.0.150:50372 (no NAT)
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: chan_sip.c:25698 handle_request_i Using INVITE request as basis request - zoLzYsUXWfaZYrFG-td34A…
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: netsock2.c:138 ast_sockaddr_split [2015-09-28 14:43:35] DEBUG[2600][C-00000000]: netsock2.c:192 ast_sockaddr_split Found peer ‘23’ for ‘23’ from 10.0.0.150:50372 5]: INVITE sip:00123480502@10.0.0.155;transport=UDP SIP/2.0
6]: Via: SIP/2.0/UDP 10.0.0.150:50372;branch=z9hG4bK-524287-1—22fd7c1c0d5fbe6f
6]: Max-Forwards: 70
8]: Contact: sip:23@10.0.0.150:50372;transport=UDP
6]: To: sip:00123480502@10.0.0.155;transport=UDP
6]: From: "23"sip:23@10.0.0.155;transport=UDP;tag=ce571443
3]: Call-ID: zoLzYsUXWfaZYrFG-td34A…
4]: CSeq: 1 INVITE
1]: Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBS CRIBE
9]: Content-Type: application/sdp
0]: Supported: replaces, norefersub, extended-refer, timer, outbound, path, X-ci sco-serviceuri
0]: User-Agent: Z 3.9.32144 r32121
8]: Allow-Events: presence, kpml
9]: Content-Length: 161
0]:
3]: v=0
5]: o=Z 0 0 IN IP4 10.0.0.150
3]: s=Z
9]: c=IN IP4 10.0.0.150
5]: t=0 0
0]: m=audio 8000 RTP/AVP 3 8 0 101
3]: a=rtpmap:101 telephone-event/8000
5]: a=fmtp:101 0-16
0]: a=sendrecv
l ID: zoLzYsUXWfaZYrFG-td34A… (Checking From) --From tag ce571443 --To-tag
.0.0.150’, our source address is ‘10.0.0.155’.
IP_TRANSPORT_UDP with address 10.0.0.155:5060
plitting ‘10.0.0.150:50372’ into…
…host ‘10.0.0.150’ and port ‘50372’.
dialog for zoLzYsUXWfaZYrFG-td34A… - INVITE (No RTP)
**** Received INVITE (5) - Command in SIP INVITE
ip_options: Begin: parsing SIP “Supported: replaces, norefersub, extended-refer, timer, outbound, path, X-cisco-serviceuri”
ip_options: Found SIP option: -replaces-
ip_options: Matched SIP option: replaces
ip_options: Found SIP option: -norefersub-
ip_options: Matched SIP option: norefersub
ip_options: Found SIP option: -extended-refer-
ip_options: Found no match for SIP option: extended-refer (Please file bug repor t!)
ip_options: Found SIP option: -timer-
ip_options: Matched SIP option: timer
ip_options: Found SIP option: -outbound-
ip_options: Matched SIP option: outbound
ip_options: Found SIP option: -path-
ip_options: Matched SIP option: path
ip_options: Found SIP option: -X-cisco-serviceuri-
ip_options: Found private SIP option, not supported: X-cisco-serviceuri
_hostport: Splitting ‘10.0.0.150:50372’ into…
_hostport: …host ‘10.0.0.150’ and port ‘50372’.
nvite: Initializing initreq for method INVITE - callid zoLzYsUXWfaZYrFG-td34A…
_hostport: Splitting ‘10.0.0.155’ into…
_hostport: …host ‘10.0.0.155’ and port ‘’.

<— SIP read from UDP:10.0.0.150:50372 —>
ACK sip:00123480502@10.0.0.155;transport=UDP SIP/2.0
Via: SIP/2.0/UDP 10.0.0.150:50372;branch=z9hG4bK-524287-1—22fd7c1c0d5fbe6f
Max-Forwards: 70
To: sip:00123480502@10.0.0.155;transport=UDP;tag=as3c5b9d5c
From: "23"sip:23@10.0.0.155;transport=UDP;tag=ce571443
Call-ID: zoLzYsUXWfaZYrFG-td34A…
CSeq: 1 ACK
Content-Length: 0

<------------->
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 0 [ 5 2]: ACK sip:00123480502@10.0.0.155;transport=UDP SIP/2.0
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 1 [ 7 6]: Via: SIP/2.0/UDP 10.0.0.150:50372;branch=z9hG4bK-524287-1—22fd7c1c0d5fbe6f
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 2 [ 1 6]: Max-Forwards: 70
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 3 [ 6 1]: To: sip:00123480502@10.0.0.155;transport=UDP;tag=as3c5b9d5c
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 4 [ 5 6]: From: "23"sip:23@10.0.0.155;transport=UDP;tag=ce571443
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 5 [ 3 3]: Call-ID: zoLzYsUXWfaZYrFG-td34A…
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 6 [ 1 1]: CSeq: 1 ACK
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 7 [ 1 7]: Content-Length: 0
— (8 headers 0 lines) —
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9055 find_call: = Looking for Cal l ID: zoLzYsUXWfaZYrFG-td34A… (Checking From) --From tag ce571443 --To-tag as3c 5b9d5c
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: chan_sip.c:28459 handle_incoming: **** Received ACK (6) - Command in SIP ACK
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: chan_sip.c:4388 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #62
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: chan_sip.c:4421 __sip_ack: Stoppi ng retransmission on ‘zoLzYsUXWfaZYrFG-td34A…’ of Response 1: Match Found

<— SIP read from UDP:10.0.0.150:50372 —>
INVITE sip:00123480502@10.0.0.155;transport=UDP SIP/2.0
Via: SIP/2.0/UDP 10.0.0.150:50372;branch=z9hG4bK-524287-1—0937534352682b08
Max-Forwards: 70
Contact: sip:23@10.0.0.150:50372;transport=UDP
To: sip:00123480502@10.0.0.155;transport=UDP
From: "23"sip:23@10.0.0.155;transport=UDP;tag=ce571443
Call-ID: zoLzYsUXWfaZYrFG-td34A…
CSeq: 2 INVITE
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIB E
Content-Type: application/sdp
Supported: replaces, norefersub, extended-refer, timer, outbound, path, X-cisco- serviceuri
User-Agent: Z 3.9.32144 r32121
Authorization: Digest username=“23”,realm=“asterisk”,nonce=“1710cba4”,uri=“sip:0 0123480502@10.0.0.155;transport=UDP”,response=“abbfe3f2beb25ff375b80229e9d267a0” ,algorithm=MD5
Allow-Events: presence, kpml
Content-Length: 161

v=0
o=Z 0 0 IN IP4 10.0.0.150
s=Z
c=IN IP4 10.0.0.150
t=0 0
m=audio 8000 RTP/AVP 3 8 0 101
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=sendrecv
<------------->
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 0 [ 5 5]: INVITE sip:00123480502@10.0.0.155;transport=UDP SIP/2.0
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 1 [ 7 6]: Via: SIP/2.0/UDP 10.0.0.150:50372;branch=z9hG4bK-524287-1—0937534352682b08
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 2 [ 1 6]: Max-Forwards: 70
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 3 [ 4 8]: Contact: sip:23@10.0.0.150:50372;transport=UDP
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 4 [ 4 6]: To: sip:00123480502@10.0.0.155;transport=UDP
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 5 [ 5 6]: From: "23"sip:23@10.0.0.155;transport=UDP;tag=ce571443
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 6 [ 3 3]: Call-ID: zoLzYsUXWfaZYrFG-td34A…
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 7 [ 1 4]: CSeq: 2 INVITE
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 8 [ 8 1]: Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBS CRIBE
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 9 [ 2 9]: Content-Type: application/sdp
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 10 [ 9 0]: Supported: replaces, norefersub, extended-refer, timer, outbound, path, X-ci sco-serviceuri
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 11 [ 3 0]: User-Agent: Z 3.9.32144 r32121
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 12 [17 4]: Authorization: Digest username=“23”,realm=“asterisk”,nonce=“1710cba4”,uri=“s ip:00123480502@10.0.0.155;transport=UDP”,response=“abbfe3f2beb25ff375b80229e9d26 7a0”,algorithm=MD5
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 13 [ 2 8]: Allow-Events: presence, kpml
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 14 [ 1 9]: Content-Length: 161
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 15 [ 0]:
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Body 0 [ 3]: v=0
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Body 1 [ 2 5]: o=Z 0 0 IN IP4 10.0.0.150
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Body 2 [ 3]: s=Z
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Body 3 [ 1 9]: c=IN IP4 10.0.0.150
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Body 4 [ 5]: t=0 0
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Body 5 [ 3 0]: m=audio 8000 RTP/AVP 3 8 0 101
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Body 6 [ 3 3]: a=rtpmap:101 telephone-event/8000
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Body 7 [ 1 5]: a=fmtp:101 0-16
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9543 parse_request: Body 8 [ 1 0]: a=sendrecv
— (15 headers 9 lines) —
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9055 find_call: = Looking for Cal l ID: zoLzYsUXWfaZYrFG-td34A… (Checking From) --From tag ce571443 --To-tag
[2015-09-28 14:43:35] DEBUG[2600]: netsock2.c:138 ast_sockaddr_split_hostport: S plitting ‘10.0.0.155’ into…
[2015-09-28 14:43:35] DEBUG[2600]: netsock2.c:192 ast_sockaddr_split_hostport: . …host ‘10.0.0.155’ and port ‘’.
[2015-09-28 14:43:35] DEBUG[2600]: netsock2.c:138 ast_sockaddr_split_hostport: S plitting ‘10.0.0.155’ into…
[2015-09-28 14:43:35] DEBUG[2600]: netsock2.c:192 ast_sockaddr_split_hostport: . …host ‘10.0.0.155’ and port ‘’.
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: chan_sip.c:28459 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: netsock2.c:138 ast_sockaddr_split _hostport: Splitting ‘10.0.0.150:50372’ into…
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: netsock2.c:192 ast_sockaddr_split _hostport: …host ‘10.0.0.150’ and port ‘50372’.
Sending to 10.0.0.150:50372 (no NAT)
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: chan_sip.c:25698 handle_request_i nvite: Initializing initreq for method INVITE - callid zoLzYsUXWfaZYrFG-td34A…
Using INVITE request as basis request - zoLzYsUXWfaZYrFG-td34A…
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: netsock2.c:138 ast_sockaddr_split _hostport: Splitting ‘10.0.0.155’ into…
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: netsock2.c:192 ast_sockaddr_split _hostport: …host ‘10.0.0.155’ and port ‘’.
Found peer ‘23’ for ‘23’ from 10.0.0.150:50372
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: rtp_engine.c:283 ast_rtp_instance _new: Using engine ‘asterisk’ for RTP instance ‘0xa497218’
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: res_rtp_asterisk.c:2423 ast_rtp_n ew: Allocated port 11832 for RTP instance ‘0xa497218’
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: netsock2.c:138 ast_sockaddr_split _hostport: Splitting ‘10.0.0.155’ into…
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: netsock2.c:192 ast_sockaddr_split _hostport: …host ‘10.0.0.155’ and port ‘’.
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: rtp_engine.c:292 ast_rtp_instance _new: RTP instance ‘0xa497218’ is setup and ready to go
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: res_rtp_asterisk.c:4589 ast_rtp_p rop_set: Setup RTCP on RTP instance ‘0xa497218’
== Using SIP RTP TOS bits 184
== Using SIP RTP CoS mark 5
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: chan_sip.c:5591 do_setnat: Settin g NAT on RTP to Off
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: chan_sip.c:9947 process_sdp: Proc essing session-level SDP v=0… UNSUPPORTED OR FAILED.
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: chan_sip.c:9947 process_sdp: Proc essing session-level SDP o=Z 0 0 IN IP4 10.0.0.150… OK.
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: chan_sip.c:9947 process_sdp: Proc essing session-level SDP s=Z… UNSUPPORTED OR FAILED.
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: netsock2.c:138 ast_sockaddr_split _hostport: Splitting ‘10.0.0.150’ into…
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: netsock2.c:192 ast_sockaddr_split _hostport: …host ‘10.0.0.150’ and port ‘’.
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: chan_sip.c:9947 process_sdp: Proc essing session-level SDP c=IN IP4 10.0.0.150… OK.
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: chan_sip.c:9947 process_sdp: Proc essing session-level SDP t=0 0… UNSUPPORTED OR FAILED.
Found RTP audio format 3
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: rtp_engine.c:557 ast_rtp_codecs_p ayloads_set_m_type: Setting payload 3 based on m type on 0x2ab7f2648530
Found RTP audio format 8
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: rtp_engine.c:557 ast_rtp_codecs_p ayloads_set_m_type: Setting payload 8 based on m type on 0x2ab7f2648530
Found RTP audio format 0
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: rtp_engine.c:557 ast_rtp_codecs_p ayloads_set_m_type: Setting payload 0 based on m type on 0x2ab7f2648530
Found RTP audio format 101
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: rtp_engine.c:557 ast_rtp_codecs_p ayloads_set_m_type: Setting payload 101 based on m type on 0x2ab7f2648530
Found audio description format telephone-event for ID 101
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: chan_sip.c:10400 process_sdp: Pro cessing media-level (audio) SDP a=rtpmap:101 telephone-event/8000… OK.
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: chan_sip.c:10400 process_sdp: Pro cessing media-level (audio) SDP a=fmtp:101 0-16… UNSUPPORTED OR FAILED.
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: chan_sip.c:10400 process_sdp: Pro cessing media-level (audio) SDP a=sendrecv… OK.
Capabilities: us - (gsm|ulaw|alaw), peer - audio=(gsm|ulaw|alaw)/video=(nothing) /text=(nothing), combined - (gsm|ulaw|alaw)
Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephon e-event|), combined - 0x1 (telephone-event|)
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: res_rtp_asterisk.c:4644 ast_rtp_r emote_address_set: Setting RTCP address on RTP instance ‘0xa497218’
Peer audio RTP is at port 10.0.0.150:8000
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: rtp_engine.c:515 ast_rtp_codecs_p ayloads_copy: Copying payload 0 from 0x2ab7f2648530 to 0xa4973e0
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: rtp_engine.c:515 ast_rtp_codecs_p ayloads_copy: Copying payload 3 from 0x2ab7f2648530 to 0xa4973e0
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: rtp_engine.c:515 ast_rtp_codecs_p ayloads_copy: Copying payload 8 from 0x2ab7f2648530 to 0xa4973e0
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: rtp_engine.c:515 ast_rtp_codecs_p ayloads_copy: Copying payload 101 from 0x2ab7f2648530 to 0xa4973e0
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: res_rtp_asterisk.c:4555 ast_rtp_p rop_set: Ignoring duplicate RTCP property on RTP instance ‘0xa497218’
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: chan_sip.c:10679 process_sdp: We’ re settling with these formats: (gsm|ulaw|alaw)
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: chan_sip.c:25825 handle_request_i nvite: Checking SIP call limits for device 23
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: chan_sip.c:6533 update_call_count er: Updating call counter for incoming call
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: chan_sip.c:6638 update_call_count er: Call from peer ‘23’ is 1 out of 2147483647
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: netsock2.c:138 ast_sockaddr_split _hostport: Splitting ‘10.0.0.155’ into…
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: netsock2.c:192 ast_sockaddr_split _hostport: …host ‘10.0.0.155’ and port ‘’.
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: netsock2.c:138 ast_sockaddr_split _hostport: Splitting ‘10.0.0.155’ into…
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: netsock2.c:192 ast_sockaddr_split hostport: …host ‘10.0.0.155’ and port ‘’.
Looking for 00123480502 in from-internal (domain 10.0.0.155)
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: chan_sip.c:25271 handle_request_i nvite_st: Incoming INVITE with ‘timer’ option supported
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: chan_sip.c:7832 sip_new: *** Our native formats are (alaw)
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: chan_sip.c:7833 sip_new: *** Join t capabilities are (gsm|ulaw|alaw)
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: chan_sip.c:7834 sip_new: *** Our capabilities are (gsm|ulaw|alaw)
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: chan_sip.c:7835 sip_new: *** AST CODEC_CHOOSE formats are alaw
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: chan_sip.c:7863 sip_new: This cha nnel will not be able to handle video.
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: chan_sip.c:16422 build_route: bui ld_route: Contact hop: sip:23@10.0.0.150:50372;transport=UDP
list_route: hop: sip:23@10.0.0.150:50372;transport=UDP
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: chan_sip.c:26021 handle_request_i nvite: SIP/23-00000000: New call is still down… Trying…

<— Transmitting (no NAT) to 10.0.0.150:50372 —>
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.0.0.150:50372;branch=z9hG4bK-524287-1—0937534352682b08;rec eived=10.0.0.150
From: "23"sip:23@10.0.0.155;transport=UDP;tag=ce571443
To: sip:00123480502@10.0.0.155;transport=UDP
Call-ID: zoLzYsUXWfaZYrFG-td34A…
CSeq: 2 INVITE
Server: FPBX-2.11.0(11.17.1)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLIS H, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: sip:00123480502@10.0.0.155:5060
Content-Length: 0

<------------>
[2015-09-28 14:43:35] DEBUG[2600][C-00000000]: chan_sip.c:3724 __sip_xmit: Tryin g to put ‘SIP/2.0 100’ onto UDP socket destined for 10.0.0.150:50372

<— SIP read from UDP:10.0.0.150:50372 —>
SUBSCRIBE sip:23@10.0.0.155;transport=UDP SIP/2.0
Via: SIP/2.0/UDP 10.0.0.150:50372;branch=z9hG4bK-524287-1—8a72cc016f83ae91
Max-Forwards: 70
Contact: sip:23@10.0.0.150:50372;transport=UDP
To: "23"sip:23@10.0.0.155;transport=UDP
From: "23"sip:23@10.0.0.155;transport=UDP;tag=4b64825e
Call-ID: BJN-i0EN3I3cBBe3jIvK9w…
CSeq: 2 SUBSCRIBE
Expires: 600
Accept: application/watcherinfo+xml
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIB E
Supported: replaces, norefersub, extended-refer, timer, outbound, path, X-cisco- serviceuri
User-Agent: Z 3.9.32144 r32121
Authorization: Digest username=“23”,realm=“asterisk”,nonce=“633faccf”,uri=“sip:2 3@10.0.0.155;transport=UDP”,response=“946b38d9d951558665c8576bd90355cd”,algorith m=MD5
Event: presence.winfo
Allow-Events: presence, kpml
Content-Length: 0

<------------->
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 0 [ 4 9]: SUBSCRIBE sip:23@10.0.0.155;transport=UDP SIP/2.0
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 1 [ 7 6]: Via: SIP/2.0/UDP 10.0.0.150:50372;branch=z9hG4bK-524287-1—8a72cc016f83ae91
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 2 [ 1 6]: Max-Forwards: 70
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 3 [ 4 8]: Contact: sip:23@10.0.0.150:50372;transport=UDP
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 4 [ 4 1]: To: "23"sip:23@10.0.0.155;transport=UDP
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 5 [ 5 6]: From: "23"sip:23@10.0.0.155;transport=UDP;tag=4b64825e
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 6 [ 3 3]: Call-ID: BJN-i0EN3I3cBBe3jIvK9w…
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 7 [ 1 7]: CSeq: 2 SUBSCRIBE
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 8 [ 1 2]: Expires: 600
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 9 [ 3 5]: Accept: application/watcherinfo+xml
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 10 [ 8 1]: Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBS CRIBE
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 11 [ 9 0]: Supported: replaces, norefersub, extended-refer, timer, outbound, path, X-ci sco-serviceuri
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 12 [ 3 0]: User-Agent: Z 3.9.32144 r32121
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 13 [16 5]: Authorization: Digest username=“23”,realm=“asterisk”,nonce=“633faccf”,uri=“s ip:23@10.0.0.155;transport=UDP”,response=“946b38d9d951558665c8576bd90355cd”,algo rithm=MD5
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 14 [ 2 1]: Event: presence.winfo
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 15 [ 2 8]: Allow-Events: presence, kpml
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9506 parse_request: Header 16 [ 1 7]: Content-Length: 0
— (17 headers 0 lines) —
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:9055 find_call: = Looking for Cal l ID: BJN-i0EN3I3cBBe3jIvK9w… (Checking From) --From tag 4b64825e --To-tag
[2015-09-28 14:43:35] DEBUG[2600]: netsock2.c:138 ast_sockaddr_split_hostport: S plitting ‘10.0.0.155’ into…
[2015-09-28 14:43:35] DEBUG[2600]: netsock2.c:192 ast_sockaddr_split_hostport: . …host ‘10.0.0.155’ and port ‘’.
[2015-09-28 14:43:35] DEBUG[2600]: netsock2.c:138 ast_sockaddr_split_hostport: S plitting ‘10.0.0.155’ into…
[2015-09-28 14:43:35] DEBUG[2600]: netsock2.c:192 ast_sockaddr_split_hostport: . …host ‘10.0.0.155’ and port ‘’.
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:28459 handle_incoming: **** Receiv ed SUBSCRIBE (10) - Command in SIP SUBSCRIBE
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:27880 handle_request_subscribe: Go t a new subscription BJN-i0EN3I3cBBe3jIvK9w… (possibly with auth) or retransmis sion
Creating new subscription
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:27913 handle_request_subscribe: In itializing initreq for method SUBSCRIBE - callid BJN-i0EN3I3cBBe3jIvK9w…
[2015-09-28 14:43:35] DEBUG[2600]: netsock2.c:138 ast_sockaddr_split_hostport: S plitting ‘10.0.0.150:50372’ into…
[2015-09-28 14:43:35] DEBUG[2600]: netsock2.c:192 ast_sockaddr_split_hostport: . …host ‘10.0.0.150’ and port ‘50372’.
Sending to 10.0.0.150:50372 (no NAT)
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:16340 build_route: build_route: Re taining previous route: sip:23@10.0.0.150:50372;transport=UDP
[2015-09-28 14:43:35] DEBUG[2600]: netsock2.c:138 ast_sockaddr_split_hostport: S plitting ‘10.0.0.155’ into…
[2015-09-28 14:43:35] DEBUG[2600]: netsock2.c:192 ast_sockaddr_split_hostport: . …host ‘10.0.0.155’ and port ‘’.
Found peer ‘23’ for ‘23’ from 10.0.0.150:50372

<— Transmitting (no NAT) to 10.0.0.150:50372 —>
SIP/2.0 489 Bad Event
Via: SIP/2.0/UDP 10.0.0.150:50372;branch=z9hG4bK-524287-1—8a72cc016f83ae91;rec eived=10.0.0.150
From: "23"sip:23@10.0.0.155;transport=UDP;tag=4b64825e
To: "23"sip:23@10.0.0.155;transport=UDP;tag=as76b0af43
Call-ID: BJN-i0EN3I3cBBe3jIvK9w…
CSeq: 2 SUBSCRIBE
Server: FPBX-2.11.0(11.17.1)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLIS H, MESSAGE
Supported: replaces, timer
Content-Length: 0
<------------>
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:3724 __sip_xmit: Trying to put ‘SI P/2.0 489’ onto UDP socket destined for 10.0.0.150:50372
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:28132 handle_request_subscribe: Re ceived SIP subscribe for unknown event package: presence.winfo
[2015-09-28 14:43:35] DEBUG[2600]: chan_sip.c:6681 sip_destroy: Destroying SIP d ialog BJN-i0EN3I3cBBe3jIvK9w…
Really destroying SIP dialog ‘BJN-i0EN3I3cBBe3jIvK9w…’ Method: SUBSCRIBE
[2015-09-28 14:43:35] DEBUG[2546]: devicestate.c:344 _ast_device_state: No provi der found, checking channel drivers for SIP - 23
[2015-09-28 14:43:35] DEBUG[2546]: chan_sip.c:29907 sip_devicestate: Checking de vice state for peer 23
[2015-09-28 14:43:35] DEBUG[2546]: devicestate.c:467 do_state_change: Changing s tate for SIP/23 - state 2 (In use)
[2015-09-28 14:43:35] DEBUG[2546]: devicestate.c:442 devstate_event: device ‘SIP /23’ state ‘2’
[2015-09-28 14:43:35] DEBUG[2546]: devicestate.c:344 _ast_device_state: No provi der found, checking channel drivers for SIP - 23
[2015-09-28 14:43:35] DEBUG[2546]: chan_sip.c:29907 sip_devicestate: Checking de vice state for peer 23
[2015-09-28 14:43:35] DEBUG[2546]: devicestate.c:467 do_state_change: Changing s tate for SIP/23 - state 2 (In use)
[2015-09-28 14:43:35] DEBUG[2546]: devicestate.c:442 devstate_event: device ‘SIP /23’ state ‘2’
[2015-09-28 14:43:35] DEBUG[2777]: manager.c:4856 match_filter: Examining event:
Event: Newchannel
Privilege: call,all
Channel: SIP/23-00000000
ChannelState: 0
ChannelStateDesc: Down
CallerIDNum: 23
CallerIDName: XanSIP
AccountCode:
Exten: 00123480502
Context: from-internal
Uniqueid: 1443458615.0

[2015-09-28 14:43:35] DEBUG[2777]: manager.c:4856 match_filter: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: SIP/23-00000000
Variable: SIPURI
Value: sip:23@10.0.0.150:50372
Uniqueid: 1443458615.0

[2015-09-28 14:43:35] DEBUG[2777]: manager.c:4856 match_filter: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: SIP/23-00000000
Variable: SIPDOMAIN
Value: 10.0.0.155
Uniqueid: 1443458615.0

[2015-09-28 14:43:35] DEBUG[2777]: manager.c:4856 match_filter: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: SIP/23-00000000
Variable: SIPCALLID
Value: zoLzYsUXWfaZYrFG-td34A…
Uniqueid: 1443458615.0

[2015-09-28 14:43:35] DEBUG[2777]: manager.c:4856 match_filter: Examining event:
Event: Newstate
Privilege: call,all
Channel: SIP/23-00000000
ChannelState: 4
ChannelStateDesc: Ring
CallerIDNum: 23
CallerIDName: XanSIP
ConnectedLineNum:
ConnectedLineName:
Uniqueid: 1443458615.0

[2015-09-28 14:43:35] DEBUG[3255][C-00000000]: pbx.c:4883 pbx_extension_helper: Launching ‘ResetCDR’
– Executing [00123480502@from-internal:1] ResetCDR(“SIP/23-00000000”, “”) i n new stack
[2015-09-28 14:43:35] DEBUG[3255][C-00000000]: pbx.c:4883 pbx_extension_helper: Launching ‘NoCDR’
– Executing [00123480502@from-internal:2] NoCDR(“SIP/23-00000000”, “”) in n ew stack
[2015-09-28 14:43:35] DEBUG[3255][C-00000000]: pbx.c:4883 pbx_extension_helper: Launching ‘Progress’
– Executing [00123480502@from-internal:3] Progress(“SIP/23-00000000”, “”) i n new stack
[2015-09-28 14:43:35] DEBUG[3255][C-00000000]: chan_sip.c:13628 transmit_respons e_with_sdp: Setting framing from config on incoming call
[2015-09-28 14:43:35] DEBUG[3255][C-00000000]: chan_sip.c:13182 add_sdp: ** Our capability: (gsm|ulaw|alaw) Video flag: True Text flag: True
[2015-09-28 14:43:35] DEBUG[3255][C-00000000]: chan_sip.c:13183 add_sdp: ** Our prefcodec: (nothing)
Audio is at 11832
Adding codec 100004 (alaw) to SDP
Adding codec 100002 (gsm) to SDP
Adding codec 100003 (ulaw) to SDP
Adding non-codec 0x1 (telephone-event) to SDP
[2015-09-28 14:43:35] DEBUG[3255][C-00000000]: chan_sip.c:13319 add_sdp: – Done with adding codecs to SDP
[2015-09-28 14:43:35] DEBUG[3255][C-00000000]: chan_sip.c:13514 add_sdp: Done bu ilding SDP. Settling with this capability: (gsm|ulaw|alaw)

<— Transmitting (no NAT) to 10.0.0.150:50372 —>
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 10.0.0.150:50372;branch=z9hG4bK-524287-1—0937534352682b08;rec eived=10.0.0.150
From: "23"sip:23@10.0.0.155;transport=UDP;tag=ce571443
To: sip:00123480502@10.0.0.155;transport=UDP;tag=as64ca3cf9
Call-ID: zoLzYsUXWfaZYrFG-td34A…
CSeq: 2 INVITE
Server: FPBX-2.11.0(11.17.1)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLIS H, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: sip:00123480502@10.0.0.155:5060
Content-Type: application/sdp
Require: timer
Content-Length: 279

v=0
o=root 1689132631 1689132631 IN IP4 10.0.0.155
s=Asterisk PBX 11.17.1
c=IN IP4 10.0.0.155
t=0 0
m=audio 11832 RTP/AVP 8 3 0 101
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

<------------>
[2015-09-28 14:43:35] DEBUG[3255][C-00000000]: chan_sip.c:3724 _sip_xmit: Tryin g to put ‘SIP/2.0 183’ onto UDP socket destined for 10.0.0.150:50372
[2015-09-28 14:43:35] DEBUG[3255][C-00000000]: pbx.c:4883 pbx_extension_helper: Launching ‘Wait’
– Executing [00123480502@from-internal:4] Wait(“SIP/23-00000000”, “1”) in n ew stack
[2015-09-28 14:43:36] DEBUG[3255][C-00000000]: channel.c:5407 set_format: Set ch annel SIP/23-00000000 to write format slin
[2015-09-28 14:43:36] DEBUG[3255][C-00000000]: channel.c:3596 ast_settimeout_ful l: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2015-09-28 14:43:36] DEBUG[3255][C-00000000]: channel.c:4857 ast_prod: Prodding channel ‘SIP/23-00000000’
[2015-09-28 14:43:36] DEBUG[3255][C-00000000]: res_rtp_asterisk.c:3325 ast_rtp_w rite: Received frame with no data for RTP instance ‘0xa497218’ so dropping frame
[2015-09-28 14:43:36] DEBUG[3255][C-00000000]: channel.c:8825 ast_channel_start silence_generator: Started silence generator on ‘SIP/23-00000000’
[2015-09-28 14:43:36] DEBUG[2548]: app_queue.c:1959 extension_state_cb: Extensio n ‘23@ext-local’ changed to state ‘2’ (In use)
[2015-09-28 14:43:36] DEBUG[2642]: app_queue.c:1860 handle_statechange: Device ’ SIP/23’ changed to state ‘2’ (In use) but we don’t care because they’re not a me mber of any queue.
[2015-09-28 14:43:36] DEBUG[2642]: app_queue.c:1860 handle_statechange: Device ’ SIP/23’ changed to state ‘2’ (In use) but we don’t care because they’re not a me mber of any queue.
[2015-09-28 14:43:36] DEBUG[2777]: manager.c:4856 match_filter: Examining event:
Event: Newexten
Privilege: dialplan,all
Channel: SIP/23-00000000
Context: from-internal
Extension: 00123480502
Priority: 1
Application: ResetCDR
AppData:
Uniqueid: 1443458615.0

[2015-09-28 14:43:36] DEBUG[2777]: manager.c:4856 match_filter: Examining event:
Event: Newexten
Privilege: dialplan,all
Channel: SIP/23-00000000
Context: from-internal
Extension: 00123480502
Priority: 2
Application: NoCDR
AppData:
Uniqueid: 1443458615.0

[2015-09-28 14:43:36] DEBUG[2777]: manager.c:4856 match_filter: Examining event:
Event: Newexten
Privilege: dialplan,all
Channel: SIP/23-00000000
Context: from-internal
Extension: 00123480502
Priority: 3
Application: Progress
AppData:
Uniqueid: 1443458615.0

[2015-09-28 14:43:36] DEBUG[2777]: manager.c:4856 match_filter: Examining event:
Event: Newexten
Privilege: dialplan,all
Channel: SIP/23-00000000
Context: from-internal
Extension: 00123480502
Priority: 4
Application: Wait
AppData: 1
Uniqueid: 1443458615.0

[2015-09-28 14:43:36] DEBUG[2777]: manager.c:4856 match_filter: Examining event:
Event: ExtensionStatus
Privilege: call,all
Exten: 23
Context: ext-local
Hint: SIP/23,CustomPresence:23
Status: 1

[2015-09-28 14:43:36] DEBUG[3255][C-00000000]: res_rtp_asterisk.c:3351 ast_rtp_w rite: Ooh, format changed from unknown to alaw
[2015-09-28 14:43:36] DEBUG[3255][C-00000000]: res_rtp_asterisk.c:3388 ast_rtp_w rite: Created smoother: format: alaw ms: 20 len: 160
[2015-09-28 14:43:36] DEBUG[3255][C-00000000]: res_rtp_asterisk.c:3213 ast_rtp_r aw_write: Starting RTCP transmission on RTP instance ‘0xa497218’
[2015-09-28 14:43:36] DEBUG[3255][C-00000000]: res_rtp_asterisk.c:4223 ast_rtp_r ead: 0xa48fb60 – Probation learning mode pass with source address 10.0.0.150:80 00
> 0xa48fb60 – Probation passed - setting RTP source address to 10.0.0.15 0:8000
[2015-09-28 14:43:37] DEBUG[3255][C-00000000]: channel.c:3596 ast_settimeout_ful l: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-09-28 14:43:37] DEBUG[3255][C-00000000]: channel.c:8860 ast_channel_stop_s ilence_generator: Stopped silence generator on ‘SIP/23-00000000’
[2015-09-28 14:43:37] DEBUG[3255][C-00000000]: channel.c:5407 set_format: Set ch annel SIP/23-00000000 to write format alaw
[2015-09-28 14:43:37] DEBUG[3255][C-00000000]: pbx.c:4883 pbx_extension_helper: Launching ‘Progress’
– Executing [00123480502@from-internal:5] Progress(“SIP/23-00000000”, “”) i n new stack
[2015-09-28 14:43:37] DEBUG[3255][C-00000000]: pbx.c:4883 pbx_extension_helper: Launching ‘Playback’
– Executing [00123480502@from-internal:6] Playback(“SIP/23-00000000”, “sile nce/1&cannot-complete-as-dialed&check-number-dial-again,noanswer”) in new stack
[2015-09-28 14:43:37] DEBUG[2777]: manager.c:4856 match_filter: Examining event:
Event: Newexten
Privilege: dialplan,all
Channel: SIP/23-00000000
Context: from-internal
Extension: 00123480502
Priority: 5
Application: Progress
AppData:
Uniqueid: 1443458615.0

[2015-09-28 14:43:37] DEBUG[2777]: manager.c:4856 match_filter: Examining event:
Event: Newexten
Privilege: dialplan,all
Channel: SIP/23-00000000
Context: from-internal
Extension: 00123480502
Priority: 6
Application: Playback
AppData: silence/1&cannot-complete-as-dialed&check-number-dial-again,noanswer
Uniqueid: 1443458615.0

[2015-09-28 14:43:37] DEBUG[3255][C-00000000]: channel.c:5407 set_format: Set ch annel SIP/23-00000000 to write format gsm
[2015-09-28 14:43:37] DEBUG[3255][C-00000000]: channel.c:3596 ast_settimeout_ful l: Scheduling timer at (50 requested / 50 actual) timer ticks per second
– <SIP/23-00000000> Playing ‘silence/1.gsm’ (language ‘en’)
[2015-09-28 14:43:38] DEBUG[3255][C-00000000]: channel.c:3596 ast_settimeout_ful l: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-09-28 14:43:38] DEBUG[3255][C-00000000]: channel.c:3596 ast_settimeout_ful l: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-09-28 14:43:38] DEBUG[3255][C-00000000]: channel.c:3596 ast_settimeout_ful l: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-09-28 14:43:38] DEBUG[3255][C-00000000]: channel.c:5407 set_format: Set ch annel SIP/23-00000000 to write format alaw
[2015-09-28 14:43:38] DEBUG[3255][C-00000000]: channel.c:5407 set_format: Set ch annel SIP/23-00000000 to write format gsm
[2015-09-28 14:43:38] DEBUG[3255][C-00000000]: channel.c:3596 ast_settimeout_ful l: Scheduling timer at (50 requested / 50 actual) timer ticks per second
– <SIP/23-00000000> Playing ‘cannot-complete-as-dialed.gsm’ (language ‘en’)
[2015-09-28 14:43:39] DEBUG[3255][C-00000000]: res_rtp_asterisk.c:3830 ast_rtcp_ read: Got RTCP report of 84 bytes
[2015-09-28 14:43:39] DEBUG[2777]: manager.c:4856 match_filter: Examining event:
Event: RTCPReceived
Privilege: reporting,all
From: 10.0.0.150:8001
PT: 200(Sender Report)
ReceptionReports: 1
SenderSSRC: 0
FractionLost: 0
PacketsLost: 0
HighestSequence: 27884
SequenceNumberCycles: 0
IAJitter: 0
LastSR: 0.0000000000
DLSR: 0.0000(sec)

[2015-09-28 14:43:40] DEBUG[3255][C-00000000]: channel.c:3596 ast_settimeout_ful l: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-09-28 14:43:40] DEBUG[3255][C-00000000]: channel.c:3596 ast_settimeout_ful l: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-09-28 14:43:40] DEBUG[3255][C-00000000]: channel.c:3596 ast_settimeout_ful l: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-09-28 14:43:40] DEBUG[3255][C-00000000]: channel.c:5407 set_format: Set ch annel SIP/23-00000000 to write format alaw
[2015-09-28 14:43:40] DEBUG[3255][C-00000000]: channel.c:5407 set_format: Set ch annel SIP/23-00000000 to write format gsm
[2015-09-28 14:43:40] DEBUG[3255][C-00000000]: channel.c:3596 ast_settimeout_ful l: Scheduling timer at (50 requested / 50 actual) timer ticks per second
– <SIP/23-00000000> Playing ‘check-number-dial-again.gsm’ (language ‘en’)
[2015-09-28 14:43:41] DEBUG[2777]: manager.c:4856 match_filter: Examining event:
Event: RTCPSent
Privilege: reporting,all
To: 10.0.0.150:8001
OurSSRC: 141526187
SentNTP: 1443458621.0091074560
SentRTP: 39680
SentPackets: 248
SentOctets: 39680
ReportBlock:
FractionLost: 0
CumulativeLoss: 0
IAJitter: 0.0006
TheirLastSR: 3971548905
DLSR: 1.4610 (sec)

[2015-09-28 14:43:42] DEBUG[3255][C-00000000]: channel.c:3596 ast_settimeout_ful l: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-09-28 14:43:42] DEBUG[3255][C-00000000]: channel.c:3596 ast_settimeout_ful l: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-09-28 14:43:42] DEBUG[3255][C-00000000]: channel.c:3596 ast_settimeout_ful l: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-09-28 14:43:42] DEBUG[3255][C-00000000]: channel.c:5407 set_format: Set ch annel SIP/23-00000000 to write format alaw
[2015-09-28 14:43:42] DEBUG[3255][C-00000000]: pbx.c:4883 pbx_extension_helper: Launching ‘Wait’
– Executing [00123480502@from-internal:7] Wait(“SIP/23-00000000”, “1”) in n ew stack
[2015-09-28 14:43:42] DEBUG[3255][C-00000000]: channel.c:5407 set_format: Set ch annel SIP/23-00000000 to write format slin
[2015-09-28 14:43:42] DEBUG[3255][C-00000000]: channel.c:3596 ast_settimeout_ful l: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2015-09-28 14:43:42] DEBUG[3255][C-00000000]: channel.c:4857 ast_prod: Prodding channel ‘SIP/23-00000000’
[2015-09-28 14:43:42] DEBUG[3255][C-00000000]: res_rtp_asterisk.c:3325 ast_rtp_w rite: Received frame with no data for RTP instance ‘0xa497218’ so dropping frame
[2015-09-28 14:43:42] DEBUG[3255][C-00000000]: channel.c:8825 ast_channel_start_ silence_generator: Started silence generator on ‘SIP/23-00000000’
[2015-09-28 14:43:42] DEBUG[2777]: manager.c:4856 match_filter: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: SIP/23-00000000
Variable: PLAYBACKSTATUS
Value: SUCCESS
Uniqueid: 1443458615.0

[2015-09-28 14:43:42] DEBUG[2777]: manager.c:4856 match_filter: Examining event:
Event: Newexten
Privilege: dialplan,all
Channel: SIP/23-00000000
Context: from-internal
Extension: 00123480502
Priority: 7
Application: Wait
AppData: 1
Uniqueid: 1443458615.0

[2015-09-28 14:43:43] DEBUG[3255][C-00000000]: channel.c:3596 ast_settimeout_ful l: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-09-28 14:43:43] DEBUG[3255][C-00000000]: channel.c:8860 ast_channel_stop_s ilence_generator: Stopped silence generator on ‘SIP/23-00000000’
[2015-09-28 14:43:43] DEBUG[3255][C-00000000]: channel.c:5407 set_format: Set ch annel SIP/23-00000000 to write format alaw
[2015-09-28 14:43:43] DEBUG[3255][C-00000000]: pbx.c:4883 pbx_extension_helper: Launching ‘Congestion’
– Executing [00123480502@from-internal:8] Congestion(“SIP/23-00000000”, "20 ") in new stack

<— Reliably Transmitting (no NAT) to 10.0.0.150:50372 —>
SIP/2.0 503 Service Unavailable
Via: SIP/2.0/UDP 10.0.0.150:50372;branch=z9hG4bK-524287-1—0937534352682b08;rec eived=10.0.0.150
From: "23"sip:23@10.0.0.155;transport=UDP;tag=ce571443
To: sip:00123480502@10.0.0.155;transport=UDP;tag=as64ca3cf9
Call-ID: zoLzYsUXWfaZYrFG-td34A…
CSeq: 2 INVITE
Server: FPBX-2.11.0(11.17.1)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLIS H, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Content-Length: 0

<------------>
[2015-09-28 14:43:43] DEBUG[3255][C-00000000]: chan_sip.c:4189 __sip_reliable_xm it: *** SIP TIMER: Initializing retransmit timer on packet: Id #68
[2015-09-28 14:43:43] DEBUG[3255][C-00000000]: chan_sip.c:3724 _sip_xmit: Tryin g to put ‘SIP/2.0 503’ onto UDP socket destined for 10.0.0.150:50372
[2015-09-28 14:43:43] DEBUG[3255][C-00000000]: chan_sip.c:3380 sip_alreadygone: Setting SIP_ALREADYGONE on dialog zoLzYsUXWfaZYrFG-td34A…
[2015-09-28 14:43:43] DEBUG[3255][C-00000000]: channel.c:2663 ast_softhangup_nol ock: Soft-Hanging up channel ‘SIP/23-00000000’
[2015-09-28 14:43:43] DEBUG[3255][C-00000000]: channel.c:5407 set_format: Set ch annel SIP/23-00000000 to write format slin
[2015-09-28 14:43:43] DEBUG[3255][C-00000000]: channel.c:3596 ast_settimeout_ful l: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2015-09-28 14:43:43] DEBUG[3255][C-00000000]: channel.c:4857 ast_prod: Prodding channel ‘SIP/23-00000000’
[2015-09-28 14:43:43] WARNING[3255][C-00000000]: channel.c:4862 ast_prod: Proddi ng channel ‘SIP/23-00000000’ failed
[2015-09-28 14:43:43] DEBUG[3255][C-00000000]: channel.c:8825 ast_channel_start silence_generator: Started silence generator on ‘SIP/23-00000000’
[2015-09-28 14:43:43] DEBUG[3255][C-00000000]: channel.c:3596 ast_settimeout_ful l: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-09-28 14:43:43] DEBUG[3255][C-00000000]: channel.c:8836 deactivate_silence _generator: Trying to stop silence generator when there is no generator on ‘SIP/ 23-00000000’
[2015-09-28 14:43:43] DEBUG[3255][C-00000000]: pbx.c:6572 __ast_pbx_run: Spawn e xtension (from-internal,00123480502,8) exited non-zero on ‘SIP/23-00000000’
== Spawn extension (from-internal, 00123480502, 8) exited non-zero on ‘SIP/23- 00000000’
[2015-09-28 14:43:43] DEBUG[3255][C-00000000]: channel.c:2663 ast_softhangup_nol ock: Soft-Hanging up channel ‘SIP/23-00000000’
[2015-09-28 14:43:43] DEBUG[3255][C-00000000]: channel.c:2663 ast_softhangup_nol ock: Soft-Hanging up channel ‘SIP/23-00000000’
[2015-09-28 14:43:43] DEBUG[3255][C-00000000]: pbx.c:4883 pbx_extension_helper: Launching ‘Hangup’
– Executing [h@from-internal:1] Hangup(“SIP/23-00000000”, “”) in new stack
[2015-09-28 14:43:43] DEBUG[3255][C-00000000]: channel.c:2663 ast_softhangup_nol ock: Soft-Hanging up channel ‘SIP/23-00000000’
[2015-09-28 14:43:43] DEBUG[3255][C-00000000]: pbx.c:6088 ast_pbx_h_exten_run: S pawn extension (from-internal,h,1) exited non-zero on ‘SIP/23-00000000’
== Spawn extension (from-internal, h, 1) exited non-zero on ‘SIP/23-00000000’
[2015-09-28 14:43:43] DEBUG[3255][C-00000000]: channel.c:2842 ast_hangup: Hangin g up channel ‘SIP/23-00000000’
[2015-09-28 14:43:43] DEBUG[3255][C-00000000]: chan_sip.c:6916 sip_hangup: Hangu p call SIP/23-00000000, SIP callid zoLzYsUXWfaZYrFG-td34A…
[2015-09-28 14:43:43] DEBUG[3255][C-00000000]: chan_sip.c:6921 sip_hangup: updat e_call_counter(23) - decrement call limit counter on hangup
[2015-09-28 14:43:43] DEBUG[3255][C-00000000]: chan_sip.c:6533 update_call_count er: Updating call counter for incoming call
[2015-09-28 14:43:43] DEBUG[3255][C-00000000]: chan_sip.c:6604 update_call_count er: Call from peer ‘23’ removed from call limit 2147483647
[2015-09-28 14:43:43] DEBUG[3255][C-00000000]: res_rtp_asterisk.c:4644 ast_rtp_r emote_address_set: Setting RTCP address on RTP instance ‘0xa497218’
[2015-09-28 14:43:43] DEBUG[2777]: manager.c:4856 match_filter: Examining event:
Event: Newexten
Privilege: dialplan,all
Channel: SIP/23-00000000
Context: from-internal
Extension: 00123480502
Priority: 8
Application: Congestion
AppData: 20
Uniqueid: 1443458615.0

Please note that I did remove some of the “Unauthorized” and “Bad Event” output, on your recommendation that this is not the issue
Kind regards

jcolp · September 29, 2015, 10:50am

This appears to be a dialplan configuration issue. Some logic for catching incorrect dialed numbers is executing in the from-internal context for “00123480502” which is causing it to play back an audio prompt and send a 503 Service Unavailable. We would need to see the dialplan logic to understand why.

xanmanza · September 29, 2015, 6:24pm

Hi JColp

Thanks for the reply, here is my extensions.conf file:

[root@localhost asterisk]# vi extensions.conf
#include extensions_custom.conf
;--------------------------------------------------------------------------------;

;*******************************************************************************
; DIALPLAN OPEN TO THE PUBLIC, USING INBOUND DIDS AND SIMILAR *
;*******************************************************************************
;

;-------------------------------------------------------------------------------
; from-digital:
;
; Context to set for PRI’s and equivalent
;
[from-digital]
include => from-pstn
;-------------------------------------------------------------------------------

;-------------------------------------------------------------------------------
; from-analog:
;
; Context to set for analog DAHDi cards and equivalent
;
[from-analog]
include => from-dahdi
;-------------------------------------------------------------------------------

;-------------------------------------------------------------------------------
; from-trunk:
;
; Context is really just an aliax of from-pstn
;
[from-trunk]
include => from-pstn
;-------------------------------------------------------------------------------

;-------------------------------------------------------------------------------
; from-pstn:
;
; Entry context for calls from the outside world to hit FreePBX
[from-pstn]
include => from-pstn-custom ; create this context in extensions_custom.conf to include customizations
include => ext-did
include => ext-did-post-custom
include => from-did-direct
include => ext-did-catchall ; THIS MUST COME AFTER ext-did
;-------------------------------------------------------------------------------

;-------------------------------------------------------------------------------
; from-pstn-e164-us:
;
; The context is designed for providers who send calls in e164 format and is
; biased towards NPA calls, callerid and dialing rules. It will do the following:
;
; DIDs in an NPA e164 format of +1NXXNXXXXXX will be converted to 10 digit DIDs
;
; DIDs in any other format will be delivered as they are, including e164 non NPA
; DIDs which means they will need the full format including the + in the inbound
; route.
;
; CallerID(number) presented in e164 non-NPA (country code other than 1) will be
; reformated from: + to 011
;
[from-pstn-e164-us]
exten => +1NXXNXXXXXX/+1NXXNXXXXXX,1,Set(CALLERID(number)=${CALLERID(number):2})
exten => _+1NXXNXXXXXX/_NXXNXXXXXX,2,Goto(from-pstn,${EXTEN:2},1)
exten => +1NXXNXXXXXX/+NX.,1,Set(CALLERID(number)=011${CALLERID(number):1})
exten => _+1NXXNXXXXXX/_011NX.,n,Goto(from-pstn,${EXTEN:2},1)
exten => _+1NXXNXXXXXX,1,Goto(from-pstn,${EXTEN:2},1)
exten => [0-9+]./+1NXXNXXXXXX,1,Set(CALLERID(number)=${CALLERID(number):2})
exten => _[0-9+]./_1NXXNXXXXXX,1,Set(CALLERID(number)=${CALLERID(number):1})
exten => _[0-9+]./_NXXNXXXXXX,n,Goto(from-pstn,${EXTEN},1)
exten => [0-9+]./+NX.,1,Set(CALLERID(number)=011${CALLERID(number):1})
exten => _[0-9+]./_011NX.,n,Goto(from-pstn,${EXTEN},1)
exten => [0-9+].,1,Goto(from-pstn,${EXTEN},1)
exten => s/+1NXXNXXXXXX,1,Set(CALLERID(number)=${CALLERID(number):2})
exten => s/NXXNXXXXXX,n,Goto(from-pstn,${EXTEN},1)
exten => s/+NX.,1,Set(CALLERID(number)=011${CALLERID(number):1})
exten => s/_011NX.,n,Goto(from-pstn,${EXTEN},1)
exten => s,1,Goto(from-pstn,${EXTEN},1)
;-------------------------------------------------------------------------------

;-------------------------------------------------------------------------------
; from-pstn-to-did:
;
; The context is designed for providers who send the DID in the TO: SIP header
; only. The format of this header is:
;
; To: sip:2125551212@172.31.74.25
;
; So the DID must be extracted between the sip: and the @, which this does
;
[from-pstn-toheader]
exten => _.,1,Goto(from-pstn,${CUT(CUT(SIP_HEADER(To),@,1),:,2)},1)
;-------------------------------------------------------------------------------

;-------------------------------------------------------------------------------
; from-sip-external
;
; This context is the default SIP context unless otherwise changed in the SIP
; Settings module or other sip configuration locations. This context is hit by
; either anonymous SIP calls or mis-configured SIP trunks when the incoming call
; can not be matched with a SIP section.
;
[from-sip-external]
exten => _.,1,NoOp(Received incoming SIP connection from unknown peer to ${EXTEN})
exten => _.,n,Set(DID=${IF($[“${EXTEN:1:2}”=“”]?s:${EXTEN})})
exten => _.,n,Goto(s,1)
exten => s,1,GotoIf($[“${ALLOW_SIP_ANON}”=“yes”]?checklang:noanonymous)
exten => s,n(checklang),GotoIf($[“${SIPLANG}”!=“”]?setlanguage:from-trunk,${DID},1)
exten => s,n(setlanguage),Set(CHANNEL(language)=${SIPLANG})
exten => s,n,Goto(from-trunk,${DID},1)
exten => s,n(noanonymous),Set(TIMEOUT(absolute)=15)
exten => s,n,Log(WARNING,“Rejecting unknown SIP connection from ${CHANNEL(recvip)}”)
exten => s,n,Answer
exten => s,n,Wait(2)
exten => s,n,Playback(ss-noservice)
exten => s,n,Playtones(congestion)
exten => s,n,Congestion(5)
exten => h,1,Hangup
exten => i,1,Hangup
exten => t,1,Hangup

;*******************************************************************************
; INTERNAL DIALPLAN, NOT OPEN TO THE PUBLIC WORLD *
;*******************************************************************************
;

;-------------------------------------------------------------------------------
; from-internal:
;
; Internal dialplan that most internal phones have access to
;
[from-internal]
include => from-internal-noxfer
include => from-internal-xfer
include => bad-number ; auto-generated
;-------------------------------------------------------------------------------

;-------------------------------------------------------------------------------
; from-internal-noxfer:
;
; Place to put internal dialplan that should not be accessible during a blind
; transfer, this context will not be visible during such.
;
[from-internal-noxfer]
include => from-internal-noxfer-custom
include => from-internal-noxfer-additional ; auto-generated
;-------------------------------------------------------------------------------

;-------------------------------------------------------------------------------
; from-internal-xfer:
;
; Place to put most internal dialplan, will be visible during normal calls and
; blind transfers.
;
[from-internal-xfer]
include => from-internal-custom
include => from-internal-additional ; auto-generated
exten => s,1,Macro(hangupcall)
exten => h,1,Macro(hangupcall)
;-------------------------------------------------------------------------------

;*******************************************************************************
; INTERNAL MACROS & SPECIAL CONTEXTS *
;*******************************************************************************
;

;-------------------------------------------------------------------------------
; from-did-direct:
;
; forces ext-findmefollow to take precedence over ext-local. Also exposed to
; the public side to allow an extension number to be used as an external DID
; without requiring inbound routes to be created, common in many PRI installations
; where the last 4 digits are used as the extnension and DIDs are delivered in
; 4 digit formats.
;
[from-did-direct]
include => ext-findmefollow
include => ext-local
;-------------------------------------------------------------------------------

;-------------------------------------------------------------------------------

navaismo · September 29, 2015, 8:52pm

Since this is an Elastix(FreePBX back end) Your dialplan its not your dialplan. You need to check your configuration at your GUI and maybe at your extensions_additional.conf(where the real dialplan lives).

Said that I saw in your messed up log this:

[quote]-- Executing [00123480502@from-internal:5] Progress(“SIP/23-00000000”, “”) i n new stack
[2015-09-28 14:43:37] DEBUG[3255][C-00000000]: pbx.c:4883 pbx_extension_helper: Launching ‘Playback’
– Executing [00123480502@from-internal:6] Playback(“SIP/23-00000000”, “silence/1&cannot-complete-as-dialed&check-number-dial-again,noanswer”) in new stack[/quote]

Usually the Cannot complete as dialed is due to a bad “outbound route” configuration. Check your outbound rules and try again. For better support I suggest you to go to forum.elastix.org or community.freepbx.org

xanmanza · September 30, 2015, 8:45am

Navaismo!
I recognise you from the Elastix forums good man.

I will be double-checking my outbound route config and trunk config this evening and will report back.

Thanks

xanmanza · September 30, 2015, 7:31pm

Hi all
My route, trunk and extension are specified as follows:
https://drive.google.com/file/d/0B3mMsvdAZddFRDNqaXRhUE02MEU/view?usp=sharing
https://drive.google.com/file/d/0B3mMsvdAZddFcnRsZ283bHZZWVk/view?usp=sharing
https://drive.google.com/file/d/0B3mMsvdAZddFZDJ3S1lKbWpONTA/view?usp=sharing
Here is the output when I try to make the call:

[2015-09-30 17:24:50] DEBUG[2600]: chan_sip.c:3491 obproxy_get: OBPROXY: Not applying OBproxy to this call
[2015-09-30 17:24:50] DEBUG[2600]: chan_sip.c:8446 change_callid_pvt: SIP call-id changed from ‘7664892b076da6a30f5e7d580344ef53@127.0.0.1:5060’ to ‘480826b3656e64050b1db1422b8e29df@10.0.0.155:5060’
[2015-09-30 17:24:50] DEBUG[2600]: chan_sip.c:3367 initialize_initreq: Initializing initreq for method OPTIONS - callid 480826b3656e64050b1db1422b8e29df@10.0.0.155:5060
Reliably Transmitting (NAT) to 10.0.0.150:50372:
OPTIONS sip:23@105.210.167.88:50372;rinstance=59c994af980e5145;transport=UDP SIP/2.0
Via: SIP/2.0/UDP 10.0.0.155:5060;branch=z9hG4bK41e8d5e9;rport
Max-Forwards: 70
From: “Unknown” sip:Unknown@10.0.0.155;tag=as264fcba8
To: sip:23@105.210.167.88:50372;rinstance=59c994af980e5145;transport=UDP
Contact: sip:Unknown@10.0.0.155:5060
Call-ID: 480826b3656e64050b1db1422b8e29df@10.0.0.155:5060
CSeq: 102 OPTIONS
User-Agent: FPBX-2.11.0(11.17.1)
Date: Wed, 30 Sep 2015 19:24:50 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0

<— SIP read from UDP:10.0.0.150:50372 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.0.0.155:5060;branch=z9hG4bK41e8d5e9;rport=5060
Contact: sip:10.0.0.150:50372
To: sip:23@105.210.167.88:50372;rinstance=59c994af980e5145;transport=UDP;tag=5362db30
From: “Unknown” sip:Unknown@10.0.0.155;tag=as264fcba8
Call-ID: 480826b3656e64050b1db1422b8e29df@10.0.0.155:5060
CSeq: 102 OPTIONS
Accept: application/sdp, application/sdp
Accept-Language: en
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE
Supported: replaces, norefersub, extended-refer, timer, outbound, path, X-cisco-serviceuri
User-Agent: Z 3.9.32144 r32121
Allow-Events: presence, kpml
Content-Length: 0
<------------->
— (14 headers 0 lines) —
[2015-09-30 17:24:50] DEBUG[2600]: chan_sip.c:4421 __sip_ack: Stopping retransmission on ‘480826b3656e64050b1db1422b8e29df@10.0.0.155:5060’ of Request 102: Match Found
Really destroying SIP dialog ‘480826b3656e64050b1db1422b8e29df@10.0.0.155:5060’ Method: OPTIONS
<— SIP read from UDP:10.0.0.150:50372 —>
PUBLISH sip:23@10.0.0.155;transport=UDP SIP/2.0
Via: SIP/2.0/UDP 105.210.167.88:50372;branch=z9hG4bK-524287-1—f7c68ca98186c123
Max-Forwards: 70
Contact: sip:23@105.210.167.88:50372;transport=UDP
To: "23"sip:23@10.0.0.155;transport=UDP
From: "23"sip:23@10.0.0.155;transport=UDP;tag=0b188c2b
Call-ID: TI4ITw7e5oeLUnp8LBB6Cg…
CSeq: 1 PUBLISH
Expires: 600
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE
Content-Type: application/pidf+xml
Supported: replaces, norefersub, extended-refer, timer, outbound, path, X-cisco-serviceuri
User-Agent: Z 3.9.32144 r32121
Event: presence
Allow-Events: presence, kpml
Content-Length: 260
<?xml version="1.0" encoding="UTF-8"?>
open On the phone

<------------->
— (16 headers 3 lines) —
Sending to 10.0.0.150:50372 (NAT)
[2015-09-30 17:25:20] DEBUG[2600]: chan_sip.c:8658 sip_alloc: Allocating new SIP dialog for TI4ITw7e5oeLUnp8LBB6Cg… - PUBLISH (No RTP)

<— Transmitting (NAT) to 10.0.0.150:50372 —>
SIP/2.0 489 Bad Event
Via: SIP/2.0/UDP 105.210.167.88:50372;branch=z9hG4bK-524287-1—f7c68ca98186c123;received=10.0.0.150;rport=50372
From: "23"sip:23@10.0.0.155;transport=UDP;tag=0b188c2b
To: "23"sip:23@10.0.0.155;transport=UDP;tag=as506138cc
Call-ID: TI4ITw7e5oeLUnp8LBB6Cg…
CSeq: 1 PUBLISH
Server: FPBX-2.11.0(11.17.1)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0
<------------>
[2015-09-30 17:25:20] DEBUG[2600]: chan_sip.c:28762 handle_request_do: SIP message could not be handled, bad request: TI4ITw7e5oeLUnp8LBB6Cg…
Really destroying SIP dialog ‘TI4ITw7e5oeLUnp8LBB6Cg…’ Method: PUBLISH

<— SIP read from UDP:10.0.0.150:50372 —>
SUBSCRIBE sip:23@10.0.0.155;transport=UDP SIP/2.0
Via: SIP/2.0/UDP 105.210.167.88:50372;branch=z9hG4bK-524287-1—5290034a16934472
Max-Forwards: 70
Contact: sip:23@105.210.167.88:50372;transport=UDP
To: "23"sip:23@10.0.0.155;transport=UDP
From: "23"sip:23@10.0.0.155;transport=UDP;tag=ee11db0a
Call-ID: x5PE1RjtKdEcnPj5zrJB6g…
CSeq: 1 SUBSCRIBE
Expires: 600
Accept: application/watcherinfo+xml
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE
Supported: replaces, norefersub, extended-refer, timer, outbound, path, X-cisco-serviceuri
User-Agent: Z 3.9.32144 r32121
Event: presence.winfo
Allow-Events: presence, kpml
Content-Length: 0

<------------->
— (16 headers 0 lines) —
Sending to 10.0.0.150:50372 (NAT)
[2015-09-30 17:25:20] DEBUG[2600]: chan_sip.c:8658 sip_alloc: Allocating new SIP dialog for x5PE1RjtKdEcnPj5zrJB6g… - SUBSCRIBE (No RTP)
Creating new subscription
Sending to 10.0.0.150:50372 (NAT)
list_route: hop: sip:23@105.210.167.88:50372;transport=UDP
Found peer ‘23’ for ‘23’ from 10.0.0.150:50372
<— Transmitting (NAT) to 10.0.0.150:50372 —>
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 105.210.167.88:50372;branch=z9hG4bK-524287-1—5290034a16934472;received=10.0.0.150;rport=50372
From: "23"sip:23@10.0.0.155;transport=UDP;tag=ee11db0a
To: "23"sip:23@10.0.0.155;transport=UDP;tag=as17a96682
Call-ID: x5PE1RjtKdEcnPj5zrJB6g…
CSeq: 1 SUBSCRIBE
Server: FPBX-2.11.0(11.17.1)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm=“asterisk”, nonce=“58e9f0af”
Content-Length: 0
<------------>
Scheduling destruction of SIP dialog ‘x5PE1RjtKdEcnPj5zrJB6g…’ in 6400 ms (Method: SUBSCRIBE)
<— SIP read from UDP:10.0.0.150:50372 —>
SUBSCRIBE sip:23@10.0.0.155;transport=UDP SIP/2.0
Via: SIP/2.0/UDP 105.210.167.88:50372;branch=z9hG4bK-524287-1—c85a6feb28cc407a
Max-Forwards: 70
Contact: sip:23@105.210.167.88:50372;transport=UDP
To: "23"sip:23@10.0.0.155;transport=UDP
From: “23"sip:23@10.0.0.155;transport=UDP;tag=ee11db0a
Call-ID: x5PE1RjtKdEcnPj5zrJB6g…
CSeq: 2 SUBSCRIBE
Expires: 600
Accept: application/watcherinfo+xml
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE
Supported: replaces, norefersub, extended-refer, timer, outbound, path, X-cisco-serviceuri
User-Agent: Z 3.9.32144 r32121
Authorization: Digest username=“23”,realm=“asterisk”,nonce=“58e9f0af”,uri="sip:23@10.0.0.155;transport=UDP”,response=“6c3af9aa4cdd6a0e18b140c0fd1951ab”,algorithm=MD5
Event: presence.winfo
Allow-Events: presence, kpml
Content-Length: 0
<------------->
— (17 headers 0 lines) —
[2015-09-30 17:25:20] DEBUG[2600]: chan_sip.c:27880 handle_request_subscribe: Got a new subscription x5PE1RjtKdEcnPj5zrJB6g… (possibly with auth) or retransmission
Creating new subscription
Sending to 10.0.0.150:50372 (NAT)
[2015-09-30 17:25:20] DEBUG[2600]: chan_sip.c:16340 build_route: build_route: Retaining previous route: sip:23@105.210.167.88:50372;transport=UDP
Found peer ‘23’ for ‘23’ from 10.0.0.150:50372
<— Transmitting (NAT) to 10.0.0.150:50372 —>
SIP/2.0 489 Bad Event
Via: SIP/2.0/UDP 105.210.167.88:50372;branch=z9hG4bK-524287-1—c85a6feb28cc407a;received=10.0.0.150;rport=50372
From: "23"sip:23@10.0.0.155;transport=UDP;tag=ee11db0a
To: "23"sip:23@10.0.0.155;transport=UDP;tag=as17a96682
Call-ID: x5PE1RjtKdEcnPj5zrJB6g…
CSeq: 2 SUBSCRIBE
Server: FPBX-2.11.0(11.17.1)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0
<------------>
Really destroying SIP dialog ‘x5PE1RjtKdEcnPj5zrJB6g…’ Method: SUBSCRIBE

<— SIP read from UDP:10.0.0.150:50372 —>
INVITE sip:0123480502@10.0.0.155;transport=UDP SIP/2.0
Via: SIP/2.0/UDP 105.210.167.88:50372;branch=z9hG4bK-524287-1—53f4135780042888
Max-Forwards: 70
Contact: sip:23@105.210.167.88:50372;transport=UDP
To: sip:0123480502@10.0.0.155;transport=UDP
From: "23"sip:23@10.0.0.155;transport=UDP;tag=3010ce34
Call-ID: eof6xtolQ9zEfn5EWZSW0Q…
CSeq: 1 INVITE
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE
Content-Type: application/sdp
Supported: replaces, norefersub, extended-refer, timer, outbound, path, X-cisco-serviceuri
User-Agent: Z 3.9.32144 r32121
Allow-Events: presence, kpml
Content-Length: 169

v=0
o=Z 0 0 IN IP4 105.210.167.88
s=Z
c=IN IP4 105.210.167.88
t=0 0
m=audio 8000 RTP/AVP 3 8 0 101
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=sendrecv
<------------->
— (14 headers 9 lines) —
Sending to 10.0.0.150:50372 (NAT)
[2015-09-30 17:25:21] DEBUG[2600]: chan_sip.c:8658 sip_alloc: Allocating new SIP dialog for eof6xtolQ9zEfn5EWZSW0Q… - INVITE (No RTP)
Sending to 10.0.0.150:50372 (NAT)
[2015-09-30 17:25:21] DEBUG[2600][C-00000025]: chan_sip.c:25698 handle_request_invite: Initializing initreq for method INVITE - callid eof6xtolQ9zEfn5EWZSW0Q…
Using INVITE request as basis request - eof6xtolQ9zEfn5EWZSW0Q…
Found peer ‘23’ for ‘23’ from 10.0.0.150:50372

<— Reliably Transmitting (NAT) to 10.0.0.150:50372 —>
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 105.210.167.88:50372;branch=z9hG4bK-524287-1—53f4135780042888;received=10.0.0.150;rport=50372
From: "23"sip:23@10.0.0.155;transport=UDP;tag=3010ce34
To: sip:0123480502@10.0.0.155;transport=UDP;tag=as0617d822
Call-ID: eof6xtolQ9zEfn5EWZSW0Q…
CSeq: 1 INVITE
Server: FPBX-2.11.0(11.17.1)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm=“asterisk”, nonce=“1f7bf9e3”
Content-Length: 0

<------------>
Scheduling destruction of SIP dialog ‘eof6xtolQ9zEfn5EWZSW0Q…’ in 6400 ms (Method: INVITE)

<— SIP read from UDP:10.0.0.150:50372 —>
ACK sip:0123480502@10.0.0.155;transport=UDP SIP/2.0
Via: SIP/2.0/UDP 105.210.167.88:50372;branch=z9hG4bK-524287-1—53f4135780042888
Max-Forwards: 70
To: sip:0123480502@10.0.0.155;transport=UDP;tag=as0617d822
From: "23"sip:23@10.0.0.155;transport=UDP;tag=3010ce34
Call-ID: eof6xtolQ9zEfn5EWZSW0Q…
CSeq: 1 ACK
Content-Length: 0

<------------->
— (8 headers 0 lines) —
[2015-09-30 17:25:21] DEBUG[2600][C-00000025]: chan_sip.c:4421 __sip_ack: Stopping retransmission on ‘eof6xtolQ9zEfn5EWZSW0Q…’ of Response 1: Match Found

<— SIP read from UDP:10.0.0.150:50372 —>
INVITE sip:0123480502@10.0.0.155;transport=UDP SIP/2.0
Via: SIP/2.0/UDP 105.210.167.88:50372;branch=z9hG4bK-524287-1—fefb82d7a62a2b35
Max-Forwards: 70
Contact: sip:23@105.210.167.88:50372;transport=UDP
To: sip:0123480502@10.0.0.155;transport=UDP
From: “23"sip:23@10.0.0.155;transport=UDP;tag=3010ce34
Call-ID: eof6xtolQ9zEfn5EWZSW0Q…
CSeq: 2 INVITE
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE
Content-Type: application/sdp
Supported: replaces, norefersub, extended-refer, timer, outbound, path, X-cisco-serviceuri
User-Agent: Z 3.9.32144 r32121
Authorization: Digest username=“23”,realm=“asterisk”,nonce=“1f7bf9e3”,uri="sip:0123480502@10.0.0.155;transport=UDP”,response=“34ca3f43c8ffb50f3d37e73fe0c22d65”,algorithm=MD5
Allow-Events: presence, kpml
Content-Length: 169

v=0
o=Z 0 0 IN IP4 105.210.167.88
s=Z
c=IN IP4 105.210.167.88
t=0 0
m=audio 8000 RTP/AVP 3 8 0 101
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=sendrecv
<------------->
— (15 headers 9 lines) —
Sending to 10.0.0.150:50372 (NAT)
[2015-09-30 17:25:21] DEBUG[2600][C-00000025]: chan_sip.c:25698 handle_request_invite: Initializing initreq for method INVITE - callid eof6xtolQ9zEfn5EWZSW0Q…
Using INVITE request as basis request - eof6xtolQ9zEfn5EWZSW0Q…
Found peer ‘23’ for ‘23’ from 10.0.0.150:50372
[2015-09-30 17:25:21] DEBUG[2600][C-00000025]: rtp_engine.c:283 ast_rtp_instance_new: Using engine ‘asterisk’ for RTP instance ‘0x2ab7f4034468’
[2015-09-30 17:25:21] DEBUG[2600][C-00000025]: res_rtp_asterisk.c:2423 ast_rtp_new: Allocated port 10186 for RTP instance ‘0x2ab7f4034468’
[2015-09-30 17:25:21] DEBUG[2600][C-00000025]: rtp_engine.c:292 ast_rtp_instance_new: RTP instance ‘0x2ab7f4034468’ is setup and ready to go
[2015-09-30 17:25:21] DEBUG[2600][C-00000025]: res_rtp_asterisk.c:4589 ast_rtp_prop_set: Setup RTCP on RTP instance ‘0x2ab7f4034468’
[2015-09-30 17:25:21] DEBUG[2600][C-00000025]: chan_sip.c:5591 do_setnat: Setting NAT on RTP to On
Found RTP audio format 3
[2015-09-30 17:25:21] DEBUG[2600][C-00000025]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 3 based on m type on 0x2ab7f2648530
Found RTP audio format 8
[2015-09-30 17:25:21] DEBUG[2600][C-00000025]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 8 based on m type on 0x2ab7f2648530
Found RTP audio format 0
[2015-09-30 17:25:21] DEBUG[2600][C-00000025]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 0 based on m type on 0x2ab7f2648530
Found RTP audio format 101
[2015-09-30 17:25:21] DEBUG[2600][C-00000025]: rtp_engine.c:557 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0x2ab7f2648530
Found audio description format telephone-event for ID 101
Capabilities: us - (gsm|ulaw|alaw), peer - audio=(gsm|ulaw|alaw)/video=(nothing)/text=(nothing), combined - (gsm|ulaw|alaw)
Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|)
[2015-09-30 17:25:21] DEBUG[2600][C-00000025]: res_rtp_asterisk.c:4644 ast_rtp_remote_address_set: Setting RTCP address on RTP instance ‘0x2ab7f4034468’
Peer audio RTP is at port 105.210.167.88:8000
[2015-09-30 17:25:21] DEBUG[2600][C-00000025]: res_rtp_asterisk.c:4555 ast_rtp_prop_set: Ignoring duplicate RTCP property on RTP instance ‘0x2ab7f4034468’
[2015-09-30 17:25:21] DEBUG[2600][C-00000025]: chan_sip.c:25825 handle_request_invite: Checking SIP call limits for device 23
Looking for 0123480502 in from-internal (domain 10.0.0.155)
list_route: hop: sip:23@105.210.167.88:50372;transport=UDP

<— Transmitting (NAT) to 10.0.0.150:50372 —>
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 105.210.167.88:50372;branch=z9hG4bK-524287-1—fefb82d7a62a2b35;received=10.0.0.150;rport=50372
From: "23"sip:23@10.0.0.155;transport=UDP;tag=3010ce34
To: sip:0123480502@10.0.0.155;transport=UDP
Call-ID: eof6xtolQ9zEfn5EWZSW0Q…
CSeq: 2 INVITE
Server: FPBX-2.11.0(11.17.1)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: sip:0123480502@10.0.0.155:5060
Content-Length: 0

<------------>
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Macro’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Set’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: Set
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘1’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Set’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: Set
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘0’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘GotoIf’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:11850 pbx_builtin_gotoif: Not taking any branch
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: GotoIf
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘1’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘ExecIf’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: ExecIf
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Set’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: Set
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘0’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘GotoIf’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:11850 pbx_builtin_gotoif: Not taking any branch
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: GotoIf
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Set’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: Set
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘0’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘GotoIf’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:11850 pbx_builtin_gotoif: Not taking any branch
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: GotoIf
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘0’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Set’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: Set
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: db.c:376 db_get_common: Unable to find key ‘23/dialopts’ in family ‘AMPUSER’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘0’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Set’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: Set
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Set’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: Set
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘0’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘GotoIf’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:11850 pbx_builtin_gotoif: Not taking any branch
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: GotoIf
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘1’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘ExecIf’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: ExecIf
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘0’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘ExecIf’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: ExecIf
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘1’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘GotoIf’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: GotoIf
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Set’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: Set
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Set’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: Set
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Set’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: Set
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Set’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: Set
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Set’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: Set
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘1’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Set’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Set’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Gosub’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_stack.c:579 gosub_exec: Channel SIP/23-0000001e has no datastore, so we’re allocating one.
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_stack.c:621 gosub_exec: Setting ‘ARG1’ to ‘out’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_stack.c:621 gosub_exec: Setting ‘ARG2’ to ‘0123480502’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_stack.c:621 gosub_exec: Setting ‘ARG3’ to ‘’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Set’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘1’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘GotoIf’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘0’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Set’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘1’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘GotoIf’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘0’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘ExecIf’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘0’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘ExecIf’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘0’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘GotoIf’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:11850 pbx_builtin_gotoif: Not taking any branch
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Set’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Set’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Set’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Set’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Set’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Set’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘2’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘2’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Set’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Set’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Goto’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘1’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘ExecIf’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘0’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘GosubIf’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Return’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Macro’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Set’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: Set
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘0’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: db.c:376 db_get_common: Unable to find key ‘23/pinless’ in family ‘AMPUSER’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: func_db.c:151 function_db_read: DB: AMPUSER/23/pinless not found in database.
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘1’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘0’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘GosubIf’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: GosubIf
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: db.c:376 db_get_common: Unable to find key ‘23/pinless’ in family ‘AMPUSER’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: func_db.c:151 function_db_read: DB: AMPUSER/23/pinless not found in database.
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘0’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘GotoIf’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:11850 pbx_builtin_gotoif: Not taking any branch
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: GotoIf
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Set’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: Set
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Set’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: Set
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Set’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: Set
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘0’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘GotoIf’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:11850 pbx_builtin_gotoif: Not taking any branch
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: GotoIf
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘0’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘GotoIf’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:11850 pbx_builtin_gotoif: Not taking any branch
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: GotoIf
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘0’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘GotoIf’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:11850 pbx_builtin_gotoif: Not taking any branch
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: GotoIf
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: db.c:376 db_get_common: Unable to find key ‘2/dialopts’ in family ‘TRUNK’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘0’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Set’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: Set
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Macro’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘0’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘ExecIf’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: ExecIf
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘0’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘ExecIf’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: ExecIf
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘0’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘1’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘0’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘1’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘GotoIf’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: GotoIf
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Set’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: Set
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: db.c:376 db_get_common: Unable to find key ‘23/emergency_cid’ in family ‘DEVICE’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: func_db.c:151 function_db_read: DB: DEVICE/23/emergency_cid not found in database.
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Set’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: Set
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Set’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: Set
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘1’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘GotoIf’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: GotoIf
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘1’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘ExecIf’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: ExecIf
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘0’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘ExecIf’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: ExecIf
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘0’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘1’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘ExecIf’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: ExecIf
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘0’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘ExecIf’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: ExecIf
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Set’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: Set
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Set’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: Set
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: Macro
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘0’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘GosubIf’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: GosubIf
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Set’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: Set
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Set’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: Set
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘0’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘ExecIf’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: ExecIf
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘0’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘ExecIf’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: ExecIf
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Macro’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘MacroExit’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: Macro
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘0’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘GotoIf’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:11850 pbx_builtin_gotoif: Not taking any branch
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: GotoIf
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘1’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘ExecIf’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: ExecIf
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘1’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘ExecIf’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: ExecIf
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘0’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘GotoIf’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:11850 pbx_builtin_gotoif: Not taking any branch
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: GotoIf
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Dial’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: chan_sip.c:30012 sip_request_call: Asked to create a SIP channel with formats: (alaw)
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: chan_sip.c:8658 sip_alloc: Allocating new SIP dialog for 6b7696fd2afbcd0d19e013d45d31435c@127.0.0.1:5060 - INVITE (No RTP)
Really destroying SIP dialog ‘6b7696fd2afbcd0d19e013d45d31435c@127.0.0.1:5060’ Method: INVITE
[2015-09-30 17:25:21] WARNING[13980][C-00000025]: app_dial.c:2437 dial_exec_full: Unable to create channel of type ‘SIP’ (cause 20 - Subscriber absent)
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_dial.c:3102 dial_exec_full: Exiting with DIALSTATUS=CHANUNAVAIL.
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: Dial
[2015-09-30 17:25:21] DEBUG[2548]: app_queue.c:1959 extension_state_cb: Extension ‘23@ext-local’ changed to state ‘2’ (In use)
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘NoOp’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: Noop
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘0’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘GotoIf’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: GotoIf
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘0’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Set’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: Set
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Goto’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: Goto
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Goto’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: Goto
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘NoOp’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: Noop
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Set’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: Set
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Macro’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Progress’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: chan_sip.c:13628 transmit_response_with_sdp: Setting framing from config on incoming call
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: chan_sip.c:13182 add_sdp: ** Our capability: (gsm|ulaw|alaw) Video flag: True Text flag: True
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: chan_sip.c:13183 add_sdp: ** Our prefcodec: (nothing)
Audio is at 10186
Adding codec 100004 (alaw) to SDP
Adding codec 100002 (gsm) to SDP
Adding codec 100003 (ulaw) to SDP
Adding non-codec 0x1 (telephone-event) to SDP

<— Transmitting (NAT) to 10.0.0.150:50372 —>
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 105.210.167.88:50372;branch=z9hG4bK-524287-1—fefb82d7a62a2b35;received=10.0.0.150;rport=50372
From: "23"sip:23@10.0.0.155;transport=UDP;tag=3010ce34
To: sip:0123480502@10.0.0.155;transport=UDP;tag=as6f98ebb6
Call-ID: eof6xtolQ9zEfn5EWZSW0Q…
CSeq: 2 INVITE
Server: FPBX-2.11.0(11.17.1)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
Contact: sip:0123480502@10.0.0.155:5060
Content-Type: application/sdp
Require: timer
Content-Length: 279

v=0
o=root 1411958868 1411958868 IN IP4 10.0.0.155
s=Asterisk PBX 11.17.1
c=IN IP4 10.0.0.155
t=0 0
m=audio 10186 RTP/AVP 8 3 0 101
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

<------------>
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: Progress
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘0’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘GotoIf’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:11850 pbx_builtin_gotoif: Not taking any branch
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: GotoIf
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4783 pbx_substitute_variables_helper_full: Expression result is ‘0’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘GotoIf’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:11850 pbx_builtin_gotoif: Not taking any branch
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: GotoIf
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Playback’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: channel.c:5407 set_format: Set channel SIP/23-0000001e to write format gsm
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: res_rtp_asterisk.c:3351 ast_rtp_write: Ooh, format changed from unknown to alaw
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: res_rtp_asterisk.c:3388 ast_rtp_write: Created smoother: format: alaw ms: 20 len: 160
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: res_rtp_asterisk.c:3213 ast_rtp_raw_write: Starting RTCP transmission on RTP instance ‘0x2ab7f4034468’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: channel.c:3596 ast_settimeout_full: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: res_rtp_asterisk.c:4223 ast_rtp_read: 0x2ab7f4014400 – Probation learning mode pass with source address 10.0.0.150:8000
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: res_rtp_asterisk.c:4644 ast_rtp_remote_address_set: Setting RTCP address on RTP instance ‘0x2ab7f4034468’
[2015-09-30 17:25:21] DEBUG[13980][C-00000025]: res_rtp_asterisk.c:4223 ast_rtp_read: 0x2ab7f4014400 – Probation learning mode pass with source address 10.0.0.150:8000
[2015-09-30 17:25:23] DEBUG[13980][C-00000025]: channel.c:3596 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-09-30 17:25:23] DEBUG[13980][C-00000025]: channel.c:3596 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-09-30 17:25:23] DEBUG[13980][C-00000025]: channel.c:3596 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-09-30 17:25:23] DEBUG[13980][C-00000025]: channel.c:5407 set_format: Set channel SIP/23-0000001e to write format alaw
[2015-09-30 17:25:23] DEBUG[13980][C-00000025]: channel.c:5407 set_format: Set channel SIP/23-0000001e to write format gsm
[2015-09-30 17:25:23] DEBUG[13980][C-00000025]: channel.c:3596 ast_settimeout_full: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2015-09-30 17:25:24] DEBUG[13980][C-00000025]: res_rtp_asterisk.c:3830 ast_rtcp_read: Got RTCP report of 84 bytes
[2015-09-30 17:25:25] DEBUG[13980][C-00000025]: channel.c:3596 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-09-30 17:25:25] DEBUG[13980][C-00000025]: channel.c:3596 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-09-30 17:25:25] DEBUG[13980][C-00000025]: channel.c:3596 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-09-30 17:25:25] DEBUG[13980][C-00000025]: channel.c:5407 set_format: Set channel SIP/23-0000001e to write format alaw
[2015-09-30 17:25:25] DEBUG[13980][C-00000025]: app_macro.c:435 _macro_exec: Executed application: Playback
[2015-09-30 17:25:25] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Congestion’

<— Reliably Transmitting (NAT) to 10.0.0.150:50372 —>
SIP/2.0 503 Service Unavailable
Via: SIP/2.0/UDP 105.210.167.88:50372;branch=z9hG4bK-524287-1—fefb82d7a62a2b35;received=10.0.0.150;rport=50372
From: "23"sip:23@10.0.0.155;transport=UDP;tag=3010ce34
To: sip:0123480502@10.0.0.155;transport=UDP;tag=as6f98ebb6
Call-ID: eof6xtolQ9zEfn5EWZSW0Q…
CSeq: 2 INVITE
Server: FPBX-2.11.0(11.17.1)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Session-Expires: 1800;refresher=uas
X-Asterisk-HangupCause: Subscriber absent
X-Asterisk-HangupCauseCode: 20
Content-Length: 0

<------------>
[2015-09-30 17:25:25] DEBUG[13980][C-00000025]: channel.c:2663 ast_softhangup_nolock: Soft-Hanging up channel ‘SIP/23-0000001e’
[2015-09-30 17:25:25] DEBUG[13980][C-00000025]: channel.c:5407 set_format: Set channel SIP/23-0000001e to write format slin
[2015-09-30 17:25:25] DEBUG[13980][C-00000025]: channel.c:3596 ast_settimeout_full: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[2015-09-30 17:25:25] DEBUG[13980][C-00000025]: channel.c:4857 ast_prod: Prodding channel ‘SIP/23-0000001e’
[2015-09-30 17:25:25] WARNING[13980][C-00000025]: channel.c:4862 ast_prod: Prodding channel ‘SIP/23-0000001e’ failed
[2015-09-30 17:25:25] DEBUG[13980][C-00000025]: channel.c:8825 ast_channel_start_silence_generator: Started silence generator on ‘SIP/23-0000001e’
[2015-09-30 17:25:25] DEBUG[13980][C-00000025]: channel.c:3596 ast_settimeout_full: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[2015-09-30 17:25:25] DEBUG[13980][C-00000025]: channel.c:8836 deactivate_silence_generator: Trying to stop silence generator when there is no generator on ‘SIP/23-0000001e’
[2015-09-30 17:25:25] DEBUG[13980][C-00000025]: pbx.c:6572 __ast_pbx_run: Spawn extension (from-internal,0123480502,6) exited non-zero on ‘SIP/23-0000001e’
[2015-09-30 17:25:25] DEBUG[13980][C-00000025]: channel.c:2663 ast_softhangup_nolock: Soft-Hanging up channel ‘SIP/23-0000001e’
[2015-09-30 17:25:25] DEBUG[13980][C-00000025]: channel.c:2663 ast_softhangup_nolock: Soft-Hanging up channel ‘SIP/23-0000001e’
[2015-09-30 17:25:25] DEBUG[13980][C-00000025]: pbx.c:4883 pbx_extension_helper: Launching ‘Hangup’
[2015-09-30 17:25:25] DEBUG[13980][C-00000025]: channel.c:2663 ast_softhangup_nolock: Soft-Hanging up channel ‘SIP/23-0000001e’
[2015-09-30 17:25:25] DEBUG[13980][C-00000025]: pbx.c:6088 ast_pbx_h_exten_run: Spawn extension (from-internal,h,1) exited non-zero on ‘SIP/23-0000001e’
[2015-09-30 17:25:25] DEBUG[13980][C-00000025]: channel.c:2842 ast_hangup: Hanging up channel ‘SIP/23-0000001e’
[2015-09-30 17:25:25] DEBUG[13980][C-00000025]: chan_sip.c:6916 sip_hangup: Hangup call SIP/23-0000001e, SIP callid eof6xtolQ9zEfn5EWZSW0Q…
[2015-09-30 17:25:25] DEBUG[13980][C-00000025]: chan_sip.c:6921 sip_hangup: update_call_counter(23) - decrement call limit counter on hangup
[2015-09-30 17:25:25] DEBUG[13980][C-00000025]: res_rtp_asterisk.c:4644 ast_rtp_remote_address_set: Setting RTCP address on RTP instance ‘0x2ab7f4034468’

<— SIP read from UDP:10.0.0.150:50372 —>
ACK sip:0123480502@10.0.0.155;transport=UDP SIP/2.0
Via: SIP/2.0/UDP 105.210.167.88:50372;branch=z9hG4bK-524287-1—fefb82d7a62a2b35
Max-Forwards: 70
To: sip:0123480502@10.0.0.155;transport=UDP;tag=as6f98ebb6
From: "23"sip:23@10.0.0.155;transport=UDP;tag=3010ce34
Call-ID: eof6xtolQ9zEfn5EWZSW0Q…
CSeq: 2 ACK
Content-Length: 0

<------------->
— (8 headers 0 lines) —
[2015-09-30 17:25:25] DEBUG[2600][C-00000025]: chan_sip.c:4421 __sip_ack: Stopping retransmission on ‘eof6xtolQ9zEfn5EWZSW0Q…’ of Response 2: Match Found
Really destroying SIP dialog ‘eof6xtolQ9zEfn5EWZSW0Q…’ Method: ACK
[2015-09-30 17:25:25] DEBUG[2600]: rtp_engine.c:226 instance_destructor: Destroyed RTP instance ‘0x2ab7f4034468’
[2015-09-30 17:25:25] DEBUG[2548]: app_queue.c:1959 extension_state_cb: Extension ‘23@ext-local’ changed to state ‘1’ (Not in use)

<— SIP read from UDP:10.0.0.150:50372 —>
PUBLISH sip:23@10.0.0.155;transport=UDP SIP/2.0
Via: SIP/2.0/UDP 105.210.167.88:50372;branch=z9hG4bK-524287-1—8eb37a95149a94c7
Max-Forwards: 70
Contact: sip:23@105.210.167.88:50372;transport=UDP
To: "23"sip:23@10.0.0.155;transport=UDP
From: "23"sip:23@10.0.0.155;transport=UDP;tag=d2790534
Call-ID: Mih44_DYoHs4SuYyw7E7GA…
CSeq: 1 PUBLISH
Expires: 600
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE
Content-Type: application/pidf+xml
Supported: replaces, norefersub, extended-refer, timer, outbound, path, X-cisco-serviceuri
User-Agent: Z 3.9.32144 r32121
Event: presence
Allow-Events: presence, kpml
Content-Length: 254
<?xml version="1.0" encoding="UTF-8"?>
open Online

<------------->
— (16 headers 3 lines) —
Sending to 10.0.0.150:50372 (NAT)
[2015-09-30 17:25:25] DEBUG[2600]: chan_sip.c:8658 sip_alloc: Allocating new SIP dialog for Mih44_DYoHs4SuYyw7E7GA… - PUBLISH (No RTP)

<— Transmitting (NAT) to 10.0.0.150:50372 —>
SIP/2.0 489 Bad Event
Via: SIP/2.0/UDP 105.210.167.88:50372;branch=z9hG4bK-524287-1—8eb37a95149a94c7;received=10.0.0.150;rport=50372
From: "23"sip:23@10.0.0.155;transport=UDP;tag=d2790534
To: "23"sip:23@10.0.0.155;transport=UDP;tag=as3b820969
Call-ID: Mih44_DYoHs4SuYyw7E7GA…
CSeq: 1 PUBLISH
Server: FPBX-2.11.0(11.17.1)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0

<------------>
[2015-09-30 17:25:25] DEBUG[2600]: chan_sip.c:28762 handle_request_do: SIP message could not be handled, bad request: Mih44_DYoHs4SuYyw7E7GA…
Really destroying SIP dialog ‘Mih44_DYoHs4SuYyw7E7GA…’ Method: PUBLISH

<— SIP read from UDP:10.0.0.150:50372 —>
SUBSCRIBE sip:23@10.0.0.155;transport=UDP SIP/2.0
Via: SIP/2.0/UDP 105.210.167.88:50372;branch=z9hG4bK-524287-1—b008e2f68fe09ac9
Max-Forwards: 70
Contact: sip:23@105.210.167.88:50372;transport=UDP
To: "23"sip:23@10.0.0.155;transport=UDP
From: "23"sip:23@10.0.0.155;transport=UDP;tag=8201ad04
Call-ID: ivWW_cHi1KgT8LxiQsKnnA…
CSeq: 1 SUBSCRIBE
Expires: 600
Accept: application/watcherinfo+xml
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE
Supported: replaces, norefersub, extended-refer, timer, outbound, path, X-cisco-serviceuri
User-Agent: Z 3.9.32144 r32121
Event: presence.winfo
Allow-Events: presence, kpml
Content-Length: 0

<------------->
— (16 headers 0 lines) —
Sending to 10.0.0.150:50372 (NAT)
[2015-09-30 17:25:25] DEBUG[2600]: chan_sip.c:8658 sip_alloc: Allocating new SIP dialog for ivWW_cHi1KgT8LxiQsKnnA… - SUBSCRIBE (No RTP)
Creating new subscription
Sending to 10.0.0.150:50372 (NAT)
list_route: hop: sip:23@105.210.167.88:50372;transport=UDP
Found peer ‘23’ for ‘23’ from 10.0.0.150:50372

<— Transmitting (NAT) to 10.0.0.150:50372 —>
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 105.210.167.88:50372;branch=z9hG4bK-524287-1—b008e2f68fe09ac9;received=10.0.0.150;rport=50372
From: "23"sip:23@10.0.0.155;transport=UDP;tag=8201ad04
To: "23"sip:23@10.0.0.155;transport=UDP;tag=as7a6962e5
Call-ID: ivWW_cHi1KgT8LxiQsKnnA…
CSeq: 1 SUBSCRIBE
Server: FPBX-2.11.0(11.17.1)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm=“asterisk”, nonce=“6ebdba32”
Content-Length: 0

<------------>
Scheduling destruction of SIP dialog ‘ivWW_cHi1KgT8LxiQsKnnA…’ in 6400 ms (Method: SUBSCRIBE)

<— SIP read from UDP:10.0.0.150:50372 —>
SUBSCRIBE sip:23@10.0.0.155;transport=UDP SIP/2.0
Via: SIP/2.0/UDP 105.210.167.88:50372;branch=z9hG4bK-524287-1—fda8d3284ca01ba1
Max-Forwards: 70
Contact: sip:23@105.210.167.88:50372;transport=UDP
To: "23"sip:23@10.0.0.155;transport=UDP
From: “23"sip:23@10.0.0.155;transport=UDP;tag=8201ad04
Call-ID: ivWW_cHi1KgT8LxiQsKnnA…
CSeq: 2 SUBSCRIBE
Expires: 600
Accept: application/watcherinfo+xml
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE
Supported: replaces, norefersub, extended-refer, timer, outbound, path, X-cisco-serviceuri
User-Agent: Z 3.9.32144 r32121
Authorization: Digest username=“23”,realm=“asterisk”,nonce=“6ebdba32”,uri="sip:23@10.0.0.155;transport=UDP”,response=“d6efb4b69b9cc0e00c6f0191433311a6”,algorithm=MD5
Event: presence.winfo
Allow-Events: presence, kpml
Content-Length: 0

<------------->
— (17 headers 0 lines) —
[2015-09-30 17:25:25] DEBUG[2600]: chan_sip.c:27880 handle_request_subscribe: Got a new subscription ivWW_cHi1KgT8LxiQsKnnA… (possibly with auth) or retransmission
Creating new subscription
Sending to 10.0.0.150:50372 (NAT)
[2015-09-30 17:25:25] DEBUG[2600]: chan_sip.c:16340 build_route: build_route: Retaining previous route: sip:23@105.210.167.88:50372;transport=UDP
Found peer ‘23’ for ‘23’ from 10.0.0.150:50372

<— Transmitting (NAT) to 10.0.0.150:50372 —>
SIP/2.0 489 Bad Event
Via: SIP/2.0/UDP 105.210.167.88:50372;branch=z9hG4bK-524287-1—fda8d3284ca01ba1;received=10.0.0.150;rport=50372
From: "23"sip:23@10.0.0.155;transport=UDP;tag=8201ad04
To: "23"sip:23@10.0.0.155;transport=UDP;tag=as7a6962e5
Call-ID: ivWW_cHi1KgT8LxiQsKnnA…
CSeq: 2 SUBSCRIBE
Server: FPBX-2.11.0(11.17.1)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0

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

The message I get back on Zoiper is: 503 Service unavailable with the audio: “All circuits are busy now, please try again later.”

Topic		Replies	Views
No outbound call with 1.6.2.13 294209 & 1.8 294207 Asterisk Support	1	280	November 14, 2010
Inbound SIP, phones don't ring Asterisk Support	12	822	August 24, 2012
Seemingly unable to call callcenters Asterisk Support	8	405	October 28, 2015
Cannot make outgoing calls or receive incoming calls on asterisk 18.23.1 Asterisk SIP	29	172	July 16, 2025
Probation passed - setting RTP source address Asterisk Support	6	1942	May 11, 2015

Cannot make outbound call 401 Unauthorized

Related topics