ATA Recieves SIP CANCEL

I’m running a fresh install of FreePBX 13.0.46 with Asterisk 11.19. I have a couple of SIP handset extensions and two ATAs, for older 900MHz phones - and I’m having an issue I can’t seem to track down:

If I dial the ATA extension from the SIP extension it rings through fine

The ATA Extension can make outbound calls fine

However, when a SIP trunk call comes in and is routed to the ATA extension, the extension rings once and returns a User Unavailable VM message for mailbox 1000 - there is not extension 1000 set up.

A SIP packet dump show: Server > ATA (INVITE); ATA>Server (TRYING); ATA>Server (RINGING); Server>ATA (CANCEL); ATA>Server (Request Terminated)

I’m really not sure where to go with this - I have tried different ATAs - tried changing around numerous settings but no change has occurred. Any thoughts would be helpful.

Below is a debug of the SIP Peer:

[code]Audio is at 14166
Adding codec 100003 (ulaw) to SDP
Adding codec 100004 (alaw) to SDP
Adding codec 100002 (gsm) to SDP
Adding codec 100011 (g726) to SDP
Adding non-codec 0x1 (telephone-event) to SDP
Reliably Transmitting (NAT) to 192.168.10.105:5060:
INVITE sip:121@192.168.10.105:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.10.9:5060;branch=z9hG4bK11f68111;rport
Max-Forwards: 70
From: “WIRELESS CALLER” sip:xxxxxxxxxx@192.168.10.9;tag=as772a53ca
To: sip:121@192.168.10.105:5060
Contact: sip:xxxxxxxxxx@192.168.10.9:5060
Call-ID: 3a81384446cb649a60c4ded2286dbee8@192.168.10.9:5060
CSeq: 102 INVITE
User-Agent: FPBX-13.0.46(11.19.0)
Date: Wed, 06 Jan 2016 03:47:21 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
P-Asserted-Identity: “WIRELESS CALLER” sip:xxxxxxxxxx@192.168.10.9
Content-Type: application/sdp
Content-Length: 314

v=0
o=root 1089436750 1089436750 IN IP4 192.168.10.9
s=Asterisk PBX 11.19.0
c=IN IP4 192.168.10.9
t=0 0
m=audio 14166 RTP/AVP 0 8 3 111 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:111 G726-32/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv


-- Called SIP/121

<— SIP read from UDP:192.168.10.105:5060 —>
SIP/2.0 100 Trying
To: sip:121@192.168.10.105:5060
From: “WIRELESS CALLER” sip:xxxxxxxxxx@192.168.10.9;tag=as772a53ca
Call-ID: 3a81384446cb649a60c4ded2286dbee8@192.168.10.9:5060
CSeq: 102 INVITE
Via: SIP/2.0/UDP 192.168.10.9:5060;branch=z9hG4bK11f68111
Server: Linksys/PAP2-2.0.13(LSb)
Content-Length: 0

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

<— SIP read from UDP:192.168.10.105:5060 —>
SIP/2.0 180 Ringing
To: sip:121@192.168.10.105:5060;tag=656771f5d694fd67i0
From: “WIRELESS CALLER” sip:xxxxxxxxxx@192.168.10.9;tag=as772a53ca
Call-ID: 3a81384446cb649a60c4ded2286dbee8@192.168.10.9:5060
CSeq: 102 INVITE
Via: SIP/2.0/UDP 192.168.10.9:5060;branch=z9hG4bK11f68111
Server: Linksys/PAP2-2.0.13(LSb)
Content-Length: 0

<------------->
— (8 headers 0 lines) —
list_route: no route
– SIP/121-0000033e is ringing
Scheduling destruction of SIP dialog ‘3a81384446cb649a60c4ded2286dbee8@192.168.10.9:5060’ in 6400 ms (Method: INVITE)
Reliably Transmitting (NAT) to 192.168.10.105:5060:
CANCEL sip:121@192.168.10.105:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.10.9:5060;branch=z9hG4bK11f68111;rport
Max-Forwards: 70
From: “WIRELESS CALLER” sip:xxxxxxxxxx@192.168.10.9;tag=as772a53ca
To: sip:121@192.168.10.105:5060
Call-ID: 3a81384446cb649a60c4ded2286dbee8@192.168.10.9:5060
CSeq: 102 CANCEL
User-Agent: FPBX-13.0.46(11.19.0)
Content-Length: 0


Scheduling destruction of SIP dialog ‘3a81384446cb649a60c4ded2286dbee8@192.168.10.9:5060’ in 6400 ms (Method: INVITE)
== Spawn extension (macro-dial-one, s, 47) exited non-zero on ‘SIP/inbound-0000033d’ in macro ‘dial-one’
== Spawn extension (macro-exten-vm, s, 16) exited non-zero on ‘SIP/inbound-0000033d’ in macro ‘exten-vm’
== Spawn extension (ext-local, 121, 2) exited non-zero on ‘SIP/inbound-0000033d’
– Executing [h@ext-local:1] Macro(“SIP/inbound-0000033d”, “hangupcall,”) in new stack
– Executing [s@macro-hangupcall:1] ExecIf(“SIP/inbound-0000033d”, “0?Set(CDR(recordingfile)=.wav)”) in new stack
– Executing [s@macro-hangupcall:2] GotoIf(“SIP/inbound-0000033d”, “1?theend”) in new stack
– Goto (macro-hangupcall,s,4)
– Executing [s@macro-hangupcall:4] ExecIf(“SIP/inbound-0000033d”, “0?Set(CDR(recordingfile)=)”) in new stack
– Executing [s@macro-hangupcall:5] Hangup(“SIP/inbound-0000033d”, “”) in new stack
== Spawn extension (macro-hangupcall, s, 5) exited non-zero on ‘SIP/inbound-0000033d’ in macro ‘hangupcall’
== Spawn extension (ext-local, h, 1) exited non-zero on ‘SIP/inbound-0000033d’

<— SIP read from UDP:192.168.10.105:5060 —>
SIP/2.0 487 Request Terminated
To: sip:121@192.168.10.105:5060;tag=656771f5d694fd67i0
From: “WIRELESS CALLER” sip:xxxxxxxxxx@192.168.10.9;tag=as772a53ca
Call-ID: 3a81384446cb649a60c4ded2286dbee8@192.168.10.9:5060
CSeq: 102 INVITE
Via: SIP/2.0/UDP 192.168.10.9:5060;branch=z9hG4bK11f68111
Server: Linksys/PAP2-2.0.13(LSb)
Content-Length: 0

<------------->
— (8 headers 0 lines) —
Transmitting (NAT) to 192.168.10.105:5060:
ACK sip:121@192.168.10.105:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.10.9:5060;branch=z9hG4bK11f68111;rport
Max-Forwards: 70
From: “WIRELESS CALLER” sip:xxxxxxxxxx@192.168.10.9;tag=as772a53ca
To: sip:121@192.168.10.105:5060;tag=656771f5d694fd67i0
Contact: sip:xxxxxxxxxx@192.168.10.9:5060
Call-ID: 3a81384446cb649a60c4ded2286dbee8@192.168.10.9:5060
CSeq: 102 ACK
User-Agent: FPBX-13.0.46(11.19.0)
Content-Length: 0


Scheduling destruction of SIP dialog ‘3a81384446cb649a60c4ded2286dbee8@192.168.10.9:5060’ in 6400 ms (Method: INVITE)

<— SIP read from UDP:192.168.10.105:5060 —>
SIP/2.0 200 OK
To: sip:121@192.168.10.105:5060;tag=656771f5d694fd67i0
From: “WIRELESS CALLER” sip:xxxxxxxxxx@192.168.10.9;tag=as772a53ca
Call-ID: 3a81384446cb649a60c4ded2286dbee8@192.168.10.9:5060
CSeq: 102 CANCEL
Via: SIP/2.0/UDP 192.168.10.9:5060;branch=z9hG4bK11f68111
Server: Linksys/PAP2-2.0.13(LSb)
Content-Length: 0

<------------->
— (8 headers 0 lines) —
[2016-01-05 21:47:30] NOTICE[1740]: chan_sip.c:15104 sip_reregister: – Re-registration for sjk3_04@inbound24.vitelity.net
[2016-01-05 21:47:30] NOTICE[1740]: chan_sip.c:23665 handle_response_register: Outbound Registration: Expiry for inbound24.vitelity.net is 60 sec (Scheduling reregistration in 45 s)
Really destroying SIP dialog ‘3a81384446cb649a60c4ded2286dbee8@192.168.10.9:5060’ Method: INVITE
[/code]

What is your Dial line? It looks like you’ve given it a short timeout, causing it to stop and cancel the dialing.

The ring time is set to 60 seconds. I tried adjusting it upwards and it makes no difference in behaviour. I ran a debug on the inbound trunk, and I see a single UNAUTHORIZED - which I attribute to registration but am not sure. As I said, calls to the SIP handsets work fine, but the ATA extensions fail.

Debug from Inbound trunk:

[code][2016-01-06 11:03:21] NOTICE[1740]: chan_sip.c:15104 sip_reregister: – Re-registration for user3_04@inbound24.vitelity.net
REGISTER 11 headers, 0 lines
Reliably Transmitting (NAT) to 66.241.96.164:5060:
REGISTER sip:inbound24.vitelity.net SIP/2.0
Via: SIP/2.0/UDP 192.168.10.9:5060;branch=z9hG4bK05441b99;rport
Max-Forwards: 70
From: sip:user3_04@inbound24.vitelity.net;tag=as74bacbce
To: sip:user3_04@inbound24.vitelity.net
Call-ID: 1f3eb96e0608d2cf5934b3c1194d77d3@192.168.10.9
CSeq: 112 REGISTER
User-Agent: FPBX-13.0.46(11.19.0)
Authorization: Digest username=“user3_04”, realm=“asterisk”, algorithm=MD5, uri=“sip:inbound24.vitelity.net”, nonce=“64ce7dae”, response="46b6307585496196f50efbd49a2a8f87"
Expires: 120
Contact: sip:s@192.168.10.9:5060
Content-Length: 0


<— SIP read from UDP:66.241.96.164:5060 —>
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.10.9:5060;branch=z9hG4bK05441b99;received=192.168.10.9;rport=5060
From: sip:user3_04@inbound24.vitelity.net;tag=as74bacbce
To: sip:user3_04@inbound24.vitelity.net
Call-ID: 1f3eb96e0608d2cf5934b3c1194d77d3@192.168.10.9
CSeq: 112 REGISTER
User-Agent: packetrino
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Content-Length: 0

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

<— SIP read from UDP:66.241.96.164:5060 —>
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 192.168.10.9:5060;branch=z9hG4bK05441b99;received=192.168.10.9;rport=5060
From: sip:user3_04@inbound24.vitelity.net;tag=as74bacbce
To: sip:user3_04@inbound24.vitelity.net;tag=as3acd8fc0
Call-ID: 1f3eb96e0608d2cf5934b3c1194d77d3@192.168.10.9
CSeq: 112 REGISTER
User-Agent: packetrino
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
WWW-Authenticate: Digest algorithm=MD5, realm=“asterisk”, nonce="61417514"
Content-Length: 0

<------------->
— (11 headers 0 lines) —
Responding to challenge, registration to domain/host name inbound24.vitelity.net
REGISTER 11 headers, 0 lines
Reliably Transmitting (NAT) to 66.241.96.164:5060:
REGISTER sip:inbound24.vitelity.net SIP/2.0
Via: SIP/2.0/UDP 192.168.10.9:5060;branch=z9hG4bK29c8d62a;rport
Max-Forwards: 70
From: sip:user3_04@inbound24.vitelity.net;tag=as74bacbce
To: sip:user3_04@inbound24.vitelity.net
Call-ID: 1f3eb96e0608d2cf5934b3c1194d77d3@192.168.10.9
CSeq: 113 REGISTER
User-Agent: FPBX-13.0.46(11.19.0)
Authorization: Digest username=“user3_04”, realm=“asterisk”, algorithm=MD5, uri=“sip:inbound24.vitelity.net”, nonce=“61417514”, response="99fe60953ff659cc7957585d021b6b40"
Expires: 120
Contact: sip:s@192.168.10.9:5060
Content-Length: 0


<— SIP read from UDP:66.241.96.164:5060 —>
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.10.9:5060;branch=z9hG4bK29c8d62a;received=192.168.10.9;rport=5060
From: sip:user3_04@inbound24.vitelity.net;tag=as74bacbce
To: sip:user3_04@inbound24.vitelity.net
Call-ID: 1f3eb96e0608d2cf5934b3c1194d77d3@192.168.10.9
CSeq: 113 REGISTER
User-Agent: packetrino
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Content-Length: 0

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

<— SIP read from UDP:66.241.96.164:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.10.9:5060;branch=z9hG4bK29c8d62a;received=192.168.10.9;rport=5060
From: sip:user3_04@inbound24.vitelity.net;tag=as74bacbce
To: sip:user3_04@inbound24.vitelity.net;tag=as3acd8fc0
Call-ID: 1f3eb96e0608d2cf5934b3c1194d77d3@192.168.10.9
CSeq: 113 REGISTER
User-Agent: packetrino
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Expires: 60
Contact: sip:s@192.168.10.9:5060;expires=60
Date: Wed, 06 Jan 2016 17:03:21 GMT
Content-Length: 0

<------------->
— (13 headers 0 lines) —
[2016-01-06 11:03:21] NOTICE[1740]: chan_sip.c:23665 handle_response_register: Outbound Registration: Expiry for inbound24.vitelity.net is 60 sec (Scheduling reregistration in 45 s)
Really destroying SIP dialog ‘1f3eb96e0608d2cf5934b3c1194d77d3@192.168.10.9’ Method: REGISTER

<— SIP read from UDP:66.241.96.164:5060 —>
INVITE sip:847npanxxx@192.168.10.9:5060 SIP/2.0
Via: SIP/2.0/UDP 66.241.96.164:5060;branch=z9hG4bK31fb712f;rport
From: “WIRELESS CALLER” sip:312npanxxx@66.241.96.164;tag=as01d49ae3
To: sip:847npanxxx@192.168.10.9:5060
Contact: sip:312npanxxx@66.241.96.164
Call-ID: 133822d520ad178b26f4ec3b793c50f7@66.241.96.164
CSeq: 102 INVITE
User-Agent: packetrino
Max-Forwards: 70
Date: Wed, 06 Jan 2016 17:03:23 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Content-Type: application/sdp
Content-Length: 334

v=0
o=root 4629 4629 IN IP4 66.241.96.164
s=session
c=IN IP4 66.241.96.164
t=0 0
m=audio 16450 RTP/AVP 0 8 3 18 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv
<------------->
— (14 headers 16 lines) —
Sending to 66.241.96.164:5060 (NAT)
Sending to 66.241.96.164:5060 (NAT)
Using INVITE request as basis request - 133822d520ad178b26f4ec3b793c50f7@66.241.96.164
Found peer ‘inbound’ for ‘312npanxxx’ from 66.241.96.164:5060
== Using SIP RTP TOS bits 184
== Using SIP RTP CoS mark 5
Found RTP audio format 0
Found RTP audio format 8
Found RTP audio format 3
Found RTP audio format 18
Found RTP audio format 101
Found audio description format PCMU for ID 0
Found audio description format PCMA for ID 8
Found audio description format GSM for ID 3
Found audio description format G729 for ID 18
Found audio description format telephone-event for ID 101
Capabilities: us - (gsm|ulaw|alaw|g726), peer - audio=(gsm|ulaw|alaw|g729)/video=(nothing)/text=(nothing), combined - (gsm|ulaw|alaw)
Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|)
Peer audio RTP is at port 66.241.96.164:16450
Looking for 847npanxxx in from-pstn (domain 192.168.10.9)
list_route: hop: sip:312npanxxx@66.241.96.164

<— Transmitting (NAT) to 66.241.96.164:5060 —>
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 66.241.96.164:5060;branch=z9hG4bK31fb712f;received=66.241.96.164;rport=5060
From: “WIRELESS CALLER” sip:312npanxxx@66.241.96.164;tag=as01d49ae3
To: sip:847npanxxx@192.168.10.9:5060
Call-ID: 133822d520ad178b26f4ec3b793c50f7@66.241.96.164
CSeq: 102 INVITE
Server: FPBX-13.0.46(11.19.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Contact: sip:847npanxxx@192.168.10.9:5060
Content-Length: 0

<------------>
– Executing [847npanxxx@from-pstn:1] Set(“SIP/inbound-00000357”, “__FROM_DID=847npanxxx”) in new stack
– Executing [847npanxxx@from-pstn:2] Gosub(“SIP/inbound-00000357”, “sub-record-check,s,1(in,847npanxxx,no)”) in new stack
– Executing [s@sub-record-check:1] GotoIf(“SIP/inbound-00000357”, “0?initialized”) in new stack
– Executing [s@sub-record-check:2] Set(“SIP/inbound-00000357”, “__REC_STATUS=INITIALIZED”) in new stack
– Executing [s@sub-record-check:3] Set(“SIP/inbound-00000357”, “NOW=1452099803”) in new stack
– Executing [s@sub-record-check:4] Set(“SIP/inbound-00000357”, “__DAY=06”) in new stack
– Executing [s@sub-record-check:5] Set(“SIP/inbound-00000357”, “__MONTH=01”) in new stack
– Executing [s@sub-record-check:6] Set(“SIP/inbound-00000357”, “__YEAR=2016”) in new stack
– Executing [s@sub-record-check:7] Set(“SIP/inbound-00000357”, “__TIMESTR=20160106-110323”) in new stack
– Executing [s@sub-record-check:8] Set(“SIP/inbound-00000357”, “__FROMEXTEN=unknown”) in new stack
– Executing [s@sub-record-check:9] Set(“SIP/inbound-00000357”, “__MON_FMT=wav”) in new stack
– Executing [s@sub-record-check:10] NoOp(“SIP/inbound-00000357”, “Recordings initialized”) in new stack
– Executing [s@sub-record-check:11] ExecIf(“SIP/inbound-00000357”, “0?Set(ARG3=dontcare)”) in new stack
– Executing [s@sub-record-check:12] Set(“SIP/inbound-00000357”, “REC_POLICY_MODE_SAVE=”) in new stack
– Executing [s@sub-record-check:13] ExecIf(“SIP/inbound-00000357”, “0?Set(REC_STATUS=NO)”) in new stack
– Executing [s@sub-record-check:14] GotoIf(“SIP/inbound-00000357”, “2?checkaction”) in new stack
– Goto (sub-record-check,s,17)
– Executing [s@sub-record-check:17] GotoIf(“SIP/inbound-00000357”, “1?sub-record-check,in,1”) in new stack
– Goto (sub-record-check,in,1)
– Executing [in@sub-record-check:1] NoOp(“SIP/inbound-00000357”, “Inbound Recording Check to 847npanxxx”) in new stack
– Executing [in@sub-record-check:2] Set(“SIP/inbound-00000357”, “FROMEXTEN=unknown”) in new stack
– Executing [in@sub-record-check:3] ExecIf(“SIP/inbound-00000357”, “10?Set(FROMEXTEN=312npanxxx)”) in new stack
– Executing [in@sub-record-check:4] Gosub(“SIP/inbound-00000357”, “recordcheck,1(no,in,847npanxxx)”) in new stack
– Executing [recordcheck@sub-record-check:1] NoOp(“SIP/inbound-00000357”, “Starting recording check against no”) in new stack
– Executing [recordcheck@sub-record-check:2] Goto(“SIP/inbound-00000357”, “no”) in new stack
– Goto (sub-record-check,recordcheck,12)
– Executing [recordcheck@sub-record-check:12] Set(“SIP/inbound-00000357”, “__REC_POLICY_MODE=NO”) in new stack
– Executing [recordcheck@sub-record-check:13] Return(“SIP/inbound-00000357”, “”) in new stack
– Executing [in@sub-record-check:5] Return(“SIP/inbound-00000357”, “”) in new stack
– Executing [847npanxxx@from-pstn:3] Gosub(“SIP/inbound-00000357”, “app-blacklist-check,s,1()”) in new stack
– Executing [s@app-blacklist-check:1] GotoIf(“SIP/inbound-00000357”, “0?blacklisted”) in new stack
– Executing [s@app-blacklist-check:2] Set(“SIP/inbound-00000357”, “CALLED_BLACKLIST=1”) in new stack
– Executing [s@app-blacklist-check:3] Return(“SIP/inbound-00000357”, “”) in new stack
– Executing [847npanxxx@from-pstn:4] Set(“SIP/inbound-00000357”, “CDR(did)=847npanxxx”) in new stack
– Executing [847npanxxx@from-pstn:5] ExecIf(“SIP/inbound-00000357”, “0 ?Set(CALLERID(name)=312npanxxx)”) in new stack
– Executing [847npanxxx@from-pstn:6] Set(“SIP/inbound-00000357”, “CHANNEL(musicclass)=default”) in new stack
– Executing [847npanxxx@from-pstn:7] Set(“SIP/inbound-00000357”, “__MOHCLASS=default”) in new stack
– Executing [847npanxxx@from-pstn:8] Ringing(“SIP/inbound-00000357”, “”) in new stack

<— Transmitting (NAT) to 66.241.96.164:5060 —>
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 66.241.96.164:5060;branch=z9hG4bK31fb712f;received=66.241.96.164;rport=5060
From: “WIRELESS CALLER” sip:312npanxxx@66.241.96.164;tag=as01d49ae3
To: sip:847npanxxx@192.168.10.9:5060;tag=as5d61125c
Call-ID: 133822d520ad178b26f4ec3b793c50f7@66.241.96.164
CSeq: 102 INVITE
Server: FPBX-13.0.46(11.19.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Contact: sip:847npanxxx@192.168.10.9:5060
Content-Length: 0

<------------>
– Executing [847npanxxx@from-pstn:9] Set(“SIP/inbound-00000357”, “__REVERSAL_REJECT=FALSE”) in new stack
– Executing [847npanxxx@from-pstn:10] GotoIf(“SIP/inbound-00000357”, “1?post-reverse-charge”) in new stack
– Goto (from-pstn,847npanxxx,12)
– Executing [847npanxxx@from-pstn:12] NoOp(“SIP/inbound-00000357”, “”) in new stack
– Executing [847npanxxx@from-pstn:13] Set(“SIP/inbound-00000357”, “__CALLINGNAMEPRES_SV=allowed_not_screened”) in new stack
– Executing [847npanxxx@from-pstn:14] Set(“SIP/inbound-00000357”, “__CALLINGNUMPRES_SV=allowed_not_screened”) in new stack
– Executing [847npanxxx@from-pstn:15] Set(“SIP/inbound-00000357”, “CALLERID(name-pres)=allowed_not_screened”) in new stack
– Executing [847npanxxx@from-pstn:16] Set(“SIP/inbound-00000357”, “CALLERID(num-pres)=allowed_not_screened”) in new stack
– Executing [847npanxxx@from-pstn:17] NoOp(“SIP/inbound-00000357”, “CallerID Entry Point”) in new stack
– Executing [847npanxxx@from-pstn:18] Goto(“SIP/inbound-00000357”, “from-did-direct,121,1”) in new stack
– Goto (from-did-direct,121,1)
– Executing [121@from-did-direct:1] GotoIf(“SIP/inbound-00000357”, “1?ext-local,121,1”) in new stack
– Goto (ext-local,121,1)
– Executing [121@ext-local:1] Set(“SIP/inbound-00000357”, “__RINGTIMER=60”) in new stack
– Executing [121@ext-local:2] Macro(“SIP/inbound-00000357”, “exten-vm,novm,121,0,0,0”) in new stack
– Executing [s@macro-exten-vm:1] Macro(“SIP/inbound-00000357”, “user-callerid,”) in new stack
– Executing [s@macro-user-callerid:1] Set(“SIP/inbound-00000357”, “TOUCH_MONITOR=1452099803.5705”) in new stack
– Executing [s@macro-user-callerid:2] Set(“SIP/inbound-00000357”, “AMPUSER=312npanxxx”) in new stack
– Executing [s@macro-user-callerid:3] GotoIf(“SIP/inbound-00000357”, “0?report”) in new stack
– Executing [s@macro-user-callerid:4] ExecIf(“SIP/inbound-00000357”, “1?Set(REALCALLERIDNUM=312npanxxx)”) in new stack
– Executing [s@macro-user-callerid:5] Set(“SIP/inbound-00000357”, “AMPUSER=”) in new stack
– Executing [s@macro-user-callerid:6] GotoIf(“SIP/inbound-00000357”, “0?limit”) in new stack
– Executing [s@macro-user-callerid:7] Set(“SIP/inbound-00000357”, “AMPUSERCIDNAME=”) in new stack
– Executing [s@macro-user-callerid:8] GotoIf(“SIP/inbound-00000357”, “1?report”) in new stack
– Goto (macro-user-callerid,s,15)
– Executing [s@macro-user-callerid:15] GotoIf(“SIP/inbound-00000357”, “0?continue”) in new stack
– Executing [s@macro-user-callerid:16] ExecIf(“SIP/inbound-00000357”, “1?Set(__CALLEE_ACCOUNCODE=)”) in new stack
– Executing [s@macro-user-callerid:17] Set(“SIP/inbound-00000357”, “__TTL=64”) in new stack
– Executing [s@macro-user-callerid:18] GotoIf(“SIP/inbound-00000357”, “1?continue”) in new stack
– Goto (macro-user-callerid,s,29)
– Executing [s@macro-user-callerid:29] Set(“SIP/inbound-00000357”, “CALLERID(number)=312npanxxx”) in new stack
– Executing [s@macro-user-callerid:30] Set(“SIP/inbound-00000357”, “CALLERID(name)=WIRELESS CALLER”) in new stack
– Executing [s@macro-user-callerid:31] Set(“SIP/inbound-00000357”, “CDR(cnum)=312npanxxx”) in new stack
– Executing [s@macro-user-callerid:32] Set(“SIP/inbound-00000357”, “CDR(cnam)=WIRELESS CALLER”) in new stack
– Executing [s@macro-user-callerid:33] Set(“SIP/inbound-00000357”, “CHANNEL(language)=en”) in new stack
– Executing [s@macro-exten-vm:2] Set(“SIP/inbound-00000357”, “RingGroupMethod=none”) in new stack
– Executing [s@macro-exten-vm:3] Set(“SIP/inbound-00000357”, “__EXTTOCALL=121”) in new stack
– Executing [s@macro-exten-vm:4] Set(“SIP/inbound-00000357”, “__PICKUPMARK=121”) in new stack
– Executing [s@macro-exten-vm:5] Set(“SIP/inbound-00000357”, “RT=”) in new stack
– Executing [s@macro-exten-vm:6] ExecIf(“SIP/inbound-00000357”, “0?Macro(vm,novm,DIRECTDIAL,)”) in new stack
– Executing [s@macro-exten-vm:7] ExecIf(“SIP/inbound-00000357”, “0?MacroExit()”) in new stack
– Executing [s@macro-exten-vm:8] Gosub(“SIP/inbound-00000357”, “sub-record-check,s,1(exten,121,dontcare)”) in new stack
– Executing [s@sub-record-check:1] GotoIf(“SIP/inbound-00000357”, “10?initialized”) in new stack
– Goto (sub-record-check,s,10)
– Executing [s@sub-record-check:10] NoOp(“SIP/inbound-00000357”, “Recordings initialized”) in new stack
– Executing [s@sub-record-check:11] ExecIf(“SIP/inbound-00000357”, “0?Set(ARG3=dontcare)”) in new stack
– Executing [s@sub-record-check:12] Set(“SIP/inbound-00000357”, “REC_POLICY_MODE_SAVE=NO”) in new stack
– Executing [s@sub-record-check:13] ExecIf(“SIP/inbound-00000357”, “0?Set(REC_STATUS=NO)”) in new stack
– Executing [s@sub-record-check:14] GotoIf(“SIP/inbound-00000357”, “5?checkaction”) in new stack
– Goto (sub-record-check,s,17)
– Executing [s@sub-record-check:17] GotoIf(“SIP/inbound-00000357”, “1?sub-record-check,exten,1”) in new stack
– Goto (sub-record-check,exten,1)
– Executing [exten@sub-record-check:1] NoOp(“SIP/inbound-00000357”, “Exten Recording Check between 312npanxxx and 121”) in new stack
– Executing [exten@sub-record-check:2] Set(“SIP/inbound-00000357”, “CALLTYPE=external”) in new stack
– Executing [exten@sub-record-check:3] ExecIf(“SIP/inbound-00000357”, “0?Set(CALLTYPE=)”) in new stack
– Executing [exten@sub-record-check:4] Set(“SIP/inbound-00000357”, “CALLEE=dontcare”) in new stack
– Executing [exten@sub-record-check:5] ExecIf(“SIP/inbound-00000357”, “0?Set(CALLEE=dontcare)”) in new stack
– Executing [exten@sub-record-check:6] GotoIf(“SIP/inbound-00000357”, “1?callee”) in new stack
– Goto (sub-record-check,exten,11)
– Executing [exten@sub-record-check:11] Gosub(“SIP/inbound-00000357”, “recordcheck,1(dontcare,external,121)”) in new stack
– Executing [recordcheck@sub-record-check:1] NoOp(“SIP/inbound-00000357”, “Starting recording check against dontcare”) in new stack
– Executing [recordcheck@sub-record-check:2] Goto(“SIP/inbound-00000357”, “dontcare”) in new stack
– Goto (sub-record-check,recordcheck,3)
– Executing [recordcheck@sub-record-check:3] Return(“SIP/inbound-00000357”, “”) in new stack
– Executing [exten@sub-record-check:12] Return(“SIP/inbound-00000357”, “”) in new stack
– Executing [s@macro-exten-vm:9] GotoIf(“SIP/inbound-00000357”, “1?macrodial”) in new stack
– Goto (macro-exten-vm,s,15)
– Executing [s@macro-exten-vm:15] GosubIf(“SIP/inbound-00000357”, “0?clrheader,1()”) in new stack
– Executing [s@macro-exten-vm:16] Macro(“SIP/inbound-00000357”, “dial-one,Ttr,121”) in new stack
– Executing [s@macro-dial-one:1] Set(“SIP/inbound-00000357”, “DEXTEN=121”) in new stack
– Executing [s@macro-dial-one:2] Set(“SIP/inbound-00000357”, “DIALSTATUS_CW=”) in new stack
– Executing [s@macro-dial-one:3] GosubIf(“SIP/inbound-00000357”, “0?screen,1()”) in new stack
– Executing [s@macro-dial-one:4] GosubIf(“SIP/inbound-00000357”, “0?cf,1()”) in new stack
– Executing [s@macro-dial-one:5] GotoIf(“SIP/inbound-00000357”, “1?skip1”) in new stack
– Goto (macro-dial-one,s,8)
– Executing [s@macro-dial-one:8] GotoIf(“SIP/inbound-00000357”, “0?nodial”) in new stack
– Executing [s@macro-dial-one:9] GotoIf(“SIP/inbound-00000357”, “0?continue”) in new stack
– Executing [s@macro-dial-one:10] Set(“SIP/inbound-00000357”, “EXTHASCW=”) in new stack
– Executing [s@macro-dial-one:11] GotoIf(“SIP/inbound-00000357”, “1?next1:cwinusebusy”) in new stack
– Goto (macro-dial-one,s,12)
– Executing [s@macro-dial-one:12] GotoIf(“SIP/inbound-00000357”, “0?docfu:skip3”) in new stack
– Goto (macro-dial-one,s,16)
– Executing [s@macro-dial-one:16] GotoIf(“SIP/inbound-00000357”, “1?next2:continue”) in new stack
– Goto (macro-dial-one,s,17)
– Executing [s@macro-dial-one:17] GotoIf(“SIP/inbound-00000357”, “1?continue”) in new stack
– Goto (macro-dial-one,s,25)
– Executing [s@macro-dial-one:25] GotoIf(“SIP/inbound-00000357”, “0?nodial”) in new stack
– Executing [s@macro-dial-one:26] GosubIf(“SIP/inbound-00000357”, “1?dstring,1():dlocal,1()”) in new stack
– Executing [dstring@macro-dial-one:1] Set(“SIP/inbound-00000357”, “DSTRING=”) in new stack
– Executing [dstring@macro-dial-one:2] Set(“SIP/inbound-00000357”, “DEVICES=121”) in new stack
– Executing [dstring@macro-dial-one:3] ExecIf(“SIP/inbound-00000357”, “0?Return()”) in new stack
– Executing [dstring@macro-dial-one:4] ExecIf(“SIP/inbound-00000357”, “0?Set(DEVICES=21)”) in new stack
– Executing [dstring@macro-dial-one:5] Set(“SIP/inbound-00000357”, “LOOPCNT=1”) in new stack
– Executing [dstring@macro-dial-one:6] Set(“SIP/inbound-00000357”, “ITER=1”) in new stack
– Executing [dstring@macro-dial-one:7] Set(“SIP/inbound-00000357”, “THISDIAL=SIP/121”) in new stack
– Executing [dstring@macro-dial-one:8] GosubIf(“SIP/inbound-00000357”, “1?zap2dahdi,1()”) in new stack
– Executing [zap2dahdi@macro-dial-one:1] ExecIf(“SIP/inbound-00000357”, “0?Return()”) in new stack
– Executing [zap2dahdi@macro-dial-one:2] Set(“SIP/inbound-00000357”, “NEWDIAL=”) in new stack
– Executing [zap2dahdi@macro-dial-one:3] Set(“SIP/inbound-00000357”, “LOOPCNT2=1”) in new stack
– Executing [zap2dahdi@macro-dial-one:4] Set(“SIP/inbound-00000357”, “ITER2=1”) in new stack
– Executing [zap2dahdi@macro-dial-one:5] Set(“SIP/inbound-00000357”, “THISPART2=SIP/121”) in new stack
– Executing [zap2dahdi@macro-dial-one:6] ExecIf(“SIP/inbound-00000357”, “0?Set(THISPART2=DAHDI/121)”) in new stack
– Executing [zap2dahdi@macro-dial-one:7] Set(“SIP/inbound-00000357”, “NEWDIAL=SIP/121&”) in new stack
– Executing [zap2dahdi@macro-dial-one:8] Set(“SIP/inbound-00000357”, “ITER2=2”) in new stack
– Executing [zap2dahdi@macro-dial-one:9] GotoIf(“SIP/inbound-00000357”, “0?begin2”) in new stack
– Executing [zap2dahdi@macro-dial-one:10] Set(“SIP/inbound-00000357”, “THISDIAL=SIP/121”) in new stack
– Executing [zap2dahdi@macro-dial-one:11] Return(“SIP/inbound-00000357”, “”) in new stack
– Executing [dstring@macro-dial-one:9] GotoIf(“SIP/inbound-00000357”, “1?docheck”) in new stack
– Goto (macro-dial-one,dstring,12)
– Executing [dstring@macro-dial-one:12] GotoIf(“SIP/inbound-00000357”, “0?skipset”) in new stack
– Executing [dstring@macro-dial-one:13] Set(“SIP/inbound-00000357”, “DSTRING=SIP/121&”) in new stack
– Executing [dstring@macro-dial-one:14] Set(“SIP/inbound-00000357”, “ITER=2”) in new stack
– Executing [dstring@macro-dial-one:15] GotoIf(“SIP/inbound-00000357”, “0?begin”) in new stack
– Executing [dstring@macro-dial-one:16] ExecIf(“SIP/inbound-00000357”, “0?Return()”) in new stack
– Executing [dstring@macro-dial-one:17] Set(“SIP/inbound-00000357”, “DSTRING=SIP/121”) in new stack
– Executing [dstring@macro-dial-one:18] Return(“SIP/inbound-00000357”, “”) in new stack
– Executing [s@macro-dial-one:27] GotoIf(“SIP/inbound-00000357”, “0?nodial”) in new stack
– Executing [s@macro-dial-one:28] GotoIf(“SIP/inbound-00000357”, “0?skiptrace”) in new stack
– Executing [s@macro-dial-one:29] GosubIf(“SIP/inbound-00000357”, “1?ctset,1():ctclear,1()”) in new stack
– Executing [ctset@macro-dial-one:1] Set(“SIP/inbound-00000357”, “DB(CALLTRACE/121)=312npanxxx”) in new stack
– Executing [ctset@macro-dial-one:2] Return(“SIP/inbound-00000357”, “”) in new stack
– Executing [s@macro-dial-one:30] Set(“SIP/inbound-00000357”, “D_OPTIONS=Ttr”) in new stack
– Executing [s@macro-dial-one:31] NoOp(“SIP/inbound-00000357”, "Blind Transfer: , Attended Transfer: , User: , Alert Info: ") in new stack
– Executing [s@macro-dial-one:32] ExecIf(“SIP/inbound-00000357”, “0?Set(ALERT_INFO=inherit)”) in new stack
– Executing [s@macro-dial-one:33] ExecIf(“SIP/inbound-00000357”, “0?Set(ALERT_INFO=inherit)”) in new stack
– Executing [s@macro-dial-one:34] ExecIf(“SIP/inbound-00000357”, “0?Set(ALERT_INFO=inherit)”) in new stack
– Executing [s@macro-dial-one:35] GosubIf(“SIP/inbound-00000357”, “0?func-set-sipheader,s,1(Alert-Info,)”) in new stack
– Executing [s@macro-dial-one:36] ExecIf(“SIP/inbound-00000357”, “1?Set(CHANNEL(musicclass)=default)”) in new stack
– Executing [s@macro-dial-one:37] GosubIf(“SIP/inbound-00000357”, “0?qwait,1()”) in new stack
– Executing [s@macro-dial-one:38] Set(“SIP/inbound-00000357”, “__CWIGNORE=”) in new stack
– Executing [s@macro-dial-one:39] Set(“SIP/inbound-00000357”, “__KEEPCID=TRUE”) in new stack
– Executing [s@macro-dial-one:40] GotoIf(“SIP/inbound-00000357”, “0?usegoto,1”) in new stack
– Executing [s@macro-dial-one:41] GotoIf(“SIP/inbound-00000357”, “1?godial”) in new stack
– Goto (macro-dial-one,s,46)
– Executing [s@macro-dial-one:46] Macro(“SIP/inbound-00000357”, “dialout-one-predial-hook,”) in new stack
– Executing [s@macro-dialout-one-predial-hook:1] MacroExit(“SIP/inbound-00000357”, “”) in new stack
– Executing [s@macro-dial-one:47] Dial(“SIP/inbound-00000357”, “SIP/121,Ttrb(func-apply-sipheaders^s^1)”) in new stack
== Using SIP RTP TOS bits 184
== Using SIP RTP CoS mark 5
– SIP/121-00000358 Internal Gosub(func-apply-sipheaders,s,1) start
– Executing [s@func-apply-sipheaders:1] NoOp(“SIP/121-00000358”, “Applying SIP Headers to channel”) in new stack
– Executing [s@func-apply-sipheaders:2] Set(“SIP/121-00000358”, “SIPHEADERKEYS=”) in new stack
– Executing [s@func-apply-sipheaders:3] While(“SIP/121-00000358”, “0”) in new stack
– Jumping to priority 7
– Executing [s@func-apply-sipheaders:8] Return(“SIP/121-00000358”, “”) in new stack
== Spawn extension (from-internal, 121, 1) exited non-zero on ‘SIP/121-00000358’
– SIP/121-00000358 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
– Called SIP/121

<— Transmitting (NAT) to 66.241.96.164:5060 —>
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 66.241.96.164:5060;branch=z9hG4bK31fb712f;received=66.241.96.164;rport=5060
From: “WIRELESS CALLER” sip:312npanxxx@66.241.96.164;tag=as01d49ae3
To: sip:847npanxxx@192.168.10.9:5060;tag=as5d61125c
Call-ID: 133822d520ad178b26f4ec3b793c50f7@66.241.96.164
CSeq: 102 INVITE
Server: FPBX-13.0.46(11.19.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Contact: sip:847npanxxx@192.168.10.9:5060
Content-Length: 0

<------------>
– SIP/121-00000358 is ringing

<— Transmitting (NAT) to 66.241.96.164:5060 —>
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 66.241.96.164:5060;branch=z9hG4bK31fb712f;received=66.241.96.164;rport=5060
From: “WIRELESS CALLER” sip:312npanxxx@66.241.96.164;tag=as01d49ae3
To: sip:847npanxxx@192.168.10.9:5060;tag=as5d61125c
Call-ID: 133822d520ad178b26f4ec3b793c50f7@66.241.96.164
CSeq: 102 INVITE
Server: FPBX-13.0.46(11.19.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Contact: sip:847npanxxx@192.168.10.9:5060
Content-Length: 0

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

<— SIP read from UDP:66.241.96.164:5060 —>
CANCEL sip:847npanxxx@192.168.10.9:5060 SIP/2.0
Via: SIP/2.0/UDP 66.241.96.164:5060;branch=z9hG4bK31fb712f;rport
From: “WIRELESS CALLER” sip:312npanxxx@66.241.96.164;tag=as01d49ae3
To: sip:847npanxxx@192.168.10.9:5060
Call-ID: 133822d520ad178b26f4ec3b793c50f7@66.241.96.164
CSeq: 102 CANCEL
User-Agent: packetrino
Max-Forwards: 70
Content-Length: 0

<------------->
— (9 headers 0 lines) —
Sending to 66.241.96.164:5060 (NAT)

<— Reliably Transmitting (NAT) to 66.241.96.164:5060 —>
SIP/2.0 487 Request Terminated
Via: SIP/2.0/UDP 66.241.96.164:5060;branch=z9hG4bK31fb712f;received=66.241.96.164;rport=5060
From: “WIRELESS CALLER” sip:312npanxxx@66.241.96.164;tag=as01d49ae3
To: sip:847npanxxx@192.168.10.9:5060;tag=as5d61125c
Call-ID: 133822d520ad178b26f4ec3b793c50f7@66.241.96.164
CSeq: 102 INVITE
Server: FPBX-13.0.46(11.19.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0

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

<— Transmitting (NAT) to 66.241.96.164:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 66.241.96.164:5060;branch=z9hG4bK31fb712f;received=66.241.96.164;rport=5060
From: “WIRELESS CALLER” sip:312npanxxx@66.241.96.164;tag=as01d49ae3
To: sip:847npanxxx@192.168.10.9:5060;tag=as5d61125c
Call-ID: 133822d520ad178b26f4ec3b793c50f7@66.241.96.164
CSeq: 102 CANCEL
Server: FPBX-13.0.46(11.19.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0

<------------>
== Spawn extension (macro-dial-one, s, 47) exited non-zero on ‘SIP/inbound-00000357’ in macro ‘dial-one’
== Spawn extension (macro-exten-vm, s, 16) exited non-zero on ‘SIP/inbound-00000357’ in macro ‘exten-vm’
== Spawn extension (ext-local, 121, 2) exited non-zero on ‘SIP/inbound-00000357’
– Executing [h@ext-local:1] Macro(“SIP/inbound-00000357”, “hangupcall,”) in new stack
– Executing [s@macro-hangupcall:1] ExecIf(“SIP/inbound-00000357”, “0?Set(CDR(recordingfile)=.wav)”) in new stack
– Executing [s@macro-hangupcall:2] GotoIf(“SIP/inbound-00000357”, “1?theend”) in new stack
– Goto (macro-hangupcall,s,4)
– Executing [s@macro-hangupcall:4] ExecIf(“SIP/inbound-00000357”, “0?Set(CDR(recordingfile)=)”) in new stack
– Executing [s@macro-hangupcall:5] Hangup(“SIP/inbound-00000357”, “”) in new stack
== Spawn extension (macro-hangupcall, s, 5) exited non-zero on ‘SIP/inbound-00000357’ in macro ‘hangupcall’
== Spawn extension (ext-local, h, 1) exited non-zero on ‘SIP/inbound-00000357’

<— SIP read from UDP:66.241.96.164:5060 —>
ACK sip:847npanxxx@192.168.10.9:5060 SIP/2.0
Via: SIP/2.0/UDP 66.241.96.164:5060;branch=z9hG4bK31fb712f;rport
From: “WIRELESS CALLER” sip:312npanxxx@66.241.96.164;tag=as01d49ae3
To: sip:847npanxxx@192.168.10.9:5060;tag=as5d61125c
Contact: sip:312npanxxx@66.241.96.164
Call-ID: 133822d520ad178b26f4ec3b793c50f7@66.241.96.164
CSeq: 102 ACK
User-Agent: packetrino
Max-Forwards: 70
Content-Length: 0

<------------->
— (10 headers 0 lines) —
Really destroying SIP dialog ‘133822d520ad178b26f4ec3b793c50f7@66.241.96.164’ Method: ACK
[/code]

In this new log you’ve provided a CANCEL was received which terminated the calling:

<--- SIP read from UDP:66.241.96.164:5060 --->
CANCEL sip:847npanxxx@192.168.10.9:5060 SIP/2.0
Via: SIP/2.0/UDP 66.241.96.164:5060;branch=z9hG4bK31fb712f;rport
From: "WIRELESS CALLER" <sip:312npanxxx@66.241.96.164>;tag=as01d49ae3
To: <sip:847npanxxx@192.168.10.9:5060>
Call-ID: 133822d520ad178b26f4ec3b793c50f7@66.241.96.164
CSeq: 102 CANCEL
User-Agent: packetrino
Max-Forwards: 70
Content-Length: 0

Was this on purpose?

The first log was a debug of the ATA handset peer - the second log was a debug of the trunk peer during the call initiation. In both cases Asterisk seems to be sending a CANCEL during the handoff/bridging between the SIP negotiation from trunk>ATA. As I mentioned, from the call perspective the routed ATA/extension rings once and then is dropped into a vm-unavailable for user 1000 (no extension 1000 is configured).

I have found the issue - the upstream SIP provider was intercepting the call and routing it to their VM system. Not sure how this got put in place, but is fixed now. Thank You!