Asterisk with Linksys SPA400

Hello there,

I have kinda got myself stuck with a slight problem with the Linksys SPA400 and Asterisk.
I have managed to make the system ring on incoming calls but the only problem is, it is not answering the incoming calls nor is it allowing to make outbound calls.

Asterisk is reporting:

<— Transmitting (NAT) to 192.168.0.4:5060 —>
SIP/2.0 489 Bad event
Via: SIP/2.0/UDP 192.168.0.4:5060;branch=z9hG4bK58300754;received=192.168.0.4
From: “SPA400” sip:SPA400@192.168.0.4;tag=as31e4fb89
To: sip:SPA400@192.168.0.24:5060;tag=as4016a87b
Call-ID: 3fdd25370b07c42769b1e2022e1f262e@192.168.0.4
CSeq: 4287 NOTIFY
Server: FPBX-2.8.1(1.8.10.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Length: 0

Several times, I don’t know if that is the problem but I hope it helps.
I have ATTEMPTED to speak to Linksys and obviously you need to be a world leader before you find the correct support channel.

I have a BT line in the UK if that helps with the configuration side of things.

I look forward to hearing from you guys

Regards

Warren Doyle
FuelledHosting

That rejection is not related to an incoming or outgoing call. Without the NOTIFY request that is being rejected, it is not possible to say why it is being rejected, although Asterisk only supports NOTIFY in very limited contexts.

Is there anything else you’d like me to post to help with the enquiry as I am seriously stuck. If this doesn’t work correctly would I best going for the SPA8800 or Digium card… All I need it to do is allow PSTN BT lines to Asterisk and there is only 2 of them at Maximum

Regards

Warren

— (11 headers 14 lines) —
Sending to 192.168.0.4:5060 (NAT)
Using INVITE request as basis request - 10196740-400a8c0-13c4-4f8e9aa4-9baa3c77-17313b8a@localhost
Found peer ‘from-SPA400’ for ‘anonymous’ from 192.168.0.4:5060
== Using SIP RTP TOS bits 184
== Using SIP RTP CoS mark 5
Found RTP audio format 8
Found RTP audio format 101
Found RTP audio format 0
Found RTP audio format 18
Found audio description format PCMA for ID 8
Found audio description format telephone-event for ID 101
Found audio description format PCMU for ID 0
Found audio description format G729 for ID 18
Capabilities: us - 0xd0e (gsm|ulaw|alaw|g726|g729|ilbc), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x10c (ulaw|alaw|g729)
Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|)
Peer audio RTP is at port 192.168.0.4:10000
Looking for SPA400 in from-SPA400 (domain 192.168.0.24)
list_route: hop: sip:01538266260@192.168.0.4:5060;transport=UDP

<— Transmitting (NAT) to 192.168.0.4:5060 —>
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.0.4:5060;branch=z9hG4bK-4f8e9aa4-9baa3c81-46ee9871;received=192.168.0.4;rport=5060
From: - 01538266260sip:anonymous@localhost;tag=400a8c0-13c4-4f8e9aa4-9baa3c81-36328618
To: sip:01538266260@192.168.0.4
Call-ID: 10196740-400a8c0-13c4-4f8e9aa4-9baa3c77-17313b8a@localhost
CSeq: 1 INVITE
Server: FPBX-2.8.1(1.8.10.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Contact: sip:SPA400@192.168.0.24:5060
Content-Length: 0

I hope this helps

Not really. You haven’t included the actual invite and you haven’t included the final response.

From what you have included, the call has been successful up to that point, although, if you don’t have G.729 licences, you may have difficulties if they decide to send G.729 audio.

A typical call setup is:

INVITE+SDP
<Trying
<Ringing
<OK+SDP
ACK

although it may vary and SDP may be included on other steps.

You have only included the analysis of the INVITE and the outgoing Trying.

Below you will find all you request - To shorten it down I deleted all the notify packets the ones that were failing as mentioned before.

I rang from Landline to Handset, Handset rang, Upon pickup nothing worked… The landline kept ringing as if I didn’t pick up.

[Apr 18 11:35:27] NOTICE[4039] chan_sip.c:    -- Re-registration for  SPA400@192.168.0.4
[Apr 18 11:35:27] VERBOSE[4039] chan_sip.c: REGISTER 10 headers, 0 lines
[Apr 18 11:35:27] VERBOSE[4039] chan_sip.c: Reliably Transmitting (NAT) to 192.168.0.4:5060:
REGISTER sip:192.168.0.4 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.24:5060;branch=z9hG4bK51b6f2e1;rport
Max-Forwards: 70
From: <sip:SPA400@192.168.0.4>;tag=as7b667be4
To: <sip:SPA400@192.168.0.4>
Call-ID: 6b3e99a163754702446fe49e271db1af@127.0.0.1
CSeq: 102 REGISTER
User-Agent: FPBX-2.9.0(1.8.10.0)
Expires: 120
Contact: <sip:SPA400@192.168.0.24:5060>
Content-Length: 0


---
[Apr 18 11:35:27] VERBOSE[4039] chan_sip.c: 
<--- SIP read from UDP:192.168.0.4:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.24:5060;branch=z9hG4bK51b6f2e1
From: <sip:SPA400@192.168.0.4>;tag=as7b667be4
To: <sip:SPA400@192.168.0.4>;tag=as12326f63
Call-ID: 6b3e99a163754702446fe49e271db1af@127.0.0.1
CSeq: 102 REGISTER
User-Agent: LINKSYS/SPA400
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER
Contact: <sip:SPA400@192.168.0.24:5060>
Date: Wed, 18 Apr 2012 11:35:27 GMT
Content-Length: 0

<------------->
[Apr 18 11:35:27] VERBOSE[4039] chan_sip.c: --- (11 headers 0 lines) ---
[Apr 18 11:35:27] VERBOSE[4039] chan_sip.c: Scheduling destruction of SIP dialog '6b3e99a163754702446fe49e271db1af@127.0.0.1' in 32000 ms (Method: REGISTER)
[Apr 18 11:35:27] NOTICE[4039] chan_sip.c: Outbound Registration: Expiry for 192.168.0.4 is 120 sec (Scheduling reregistration in 105 s)
[Apr 18 11:35:27] VERBOSE[4039] chan_sip.c: 
<--- SIP read from UDP:192.168.0.4:5060 --->
NOTIFY sip:SPA400@192.168.0.24:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.4:5060;branch=z9hG4bK3b8b89dd
From: "SPA400" <sip:SPA400@192.168.0.4>;tag=as12326f63
To: <sip:SPA400@192.168.0.24:5060>
Contact: <sip:SPA400@192.168.0.4>
Call-ID: 5046738350c533594e64ebc5536d80d3@192.168.0.4
CSeq: 348 NOTIFY
User-Agent: LINKSYS/SPA400
Event: fxo-port-state;full;1=na,v=0;2=na,v=0;3=na,v=0;4=na,v=0
Content-Length: 0




[Apr 18 11:35:27] VERBOSE[4039] chan_sip.c: Scheduling destruction of SIP dialog '5046738350c533594e64ebc5536d80d3@192.168.0.4' in 32000 ms (Method: NOTIFY)
[Apr 18 11:35:27] NOTICE[4039] chan_sip.c:    -- Re-registration for  30153925@sip.voipfone.net
[Apr 18 11:35:27] NOTICE[4039] chan_sip.c:    -- Re-registration for  1483206@sipgate.co.uk
[Apr 18 11:35:27] NOTICE[4039] chan_sip.c: Outbound Registration: Expiry for sip.voipfone.net is 60 sec (Scheduling reregistration in 45 s)
[Apr 18 11:35:27] NOTICE[4039] chan_sip.c: Outbound Registration: Expiry for sipgate.co.uk is 120 sec (Scheduling reregistration in 105 s)
[Apr 18 11:35:30] VERBOSE[3583] asterisk.c:     -- Remote UNIX connection
[Apr 18 11:35:31] VERBOSE[4039] chan_sip.c: 
<--- SIP read from UDP:192.168.0.4:5060 --->
NOTIFY sip:SPA400@192.168.0.24:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.4:5060;branch=z9hG4bK7b4d2994
From: "SPA400" <sip:SPA400@192.168.0.4>;tag=as12326f63
To: <sip:SPA400@192.168.0.24:5060>
Contact: <sip:SPA400@192.168.0.4>
Call-ID: 0506e00e35fee63433aa6a353a25d5b1@192.168.0.4
CSeq: 349 NOTIFY
User-Agent: LINKSYS/SPA400
Event: fxo-port-state;partial;1=on,v=-3
Content-Length: 0


[Apr 18 11:35:31] VERBOSE[4039] chan_sip.c: Scheduling destruction of SIP dialog '0506e00e35fee63433aa6a353a25d5b1@192.168.0.4' in 32000 ms (Method: NOTIFY)
[Apr 18 11:35:32] VERBOSE[4039] chan_sip.c: Really destroying SIP dialog '3ebf43ba0a99c3e55684a03b78e50d15@192.168.0.4' Method: NOTIFY
[Apr 18 11:35:35] VERBOSE[4039] chan_sip.c: Really destroying SIP dialog '269d9b8815d64620551848ad4be5be1f@192.168.0.4' Method: NOTIFY
[Apr 18 11:35:35] VERBOSE[4039] chan_sip.c: Really destroying SIP dialog '6989fd96439b36ba561de57c4e71697c@192.168.0.4' Method: NOTIFY
[Apr 18 11:35:35] VERBOSE[4039] chan_sip.c: Really destroying SIP dialog '0165e9072413209a3181757b0d176b4c@192.168.0.4' Method: NOTIFY
[Apr 18 11:35:36] VERBOSE[4039] chan_sip.c: Really destroying SIP dialog '72f9dae4798e67f43582ee6a18b4be4e@192.168.0.4' Method: NOTIFY
[Apr 18 11:35:36] VERBOSE[4039] chan_sip.c: 
<--- SIP read from UDP:192.168.0.4:5060 --->
NOTIFY sip:SPA400@192.168.0.24:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.4:5060;branch=z9hG4bK658aae7d
From: "SPA400" <sip:SPA400@192.168.0.4>;tag=as12326f63
To: <sip:SPA400@192.168.0.24:5060>
Contact: <sip:SPA400@192.168.0.4>
Call-ID: 4975ad494599e3c64b92ed325ba1f651@192.168.0.4
CSeq: 350 NOTIFY
User-Agent: LINKSYS/SPA400
Event: fxo-port-state;partial;1=na,v=0
Content-Length: 0


[Apr 18 11:35:36] VERBOSE[4039] chan_sip.c: Scheduling destruction of SIP dialog '4975ad494599e3c64b92ed325ba1f651@192.168.0.4' in 32000 ms (Method: NOTIFY)
[Apr 18 11:35:36] VERBOSE[4039] chan_sip.c: Really destroying SIP dialog '70b0e0935823f4a0121171c82f70244e@192.168.0.4' Method: NOTIFY
[Apr 18 11:35:37] VERBOSE[4039] chan_sip.c: 
<--- SIP read from UDP:192.168.0.4:5060 --->
NOTIFY sip:SPA400@192.168.0.24:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.4:5060;branch=z9hG4bK393a64be
From: "SPA400" <sip:SPA400@192.168.0.4>;tag=as12326f63
To: <sip:SPA400@192.168.0.24:5060>
Contact: <sip:SPA400@192.168.0.4>
Call-ID: 031b1f23085f6bef4c2f6532193aaf9c@192.168.0.4
CSeq: 351 NOTIFY
User-Agent: LINKSYS/SPA400
Event: fxo-port-state;partial;1=on,v=0
Content-Length: 0



<------------>
[Apr 18 11:35:37] VERBOSE[4039] chan_sip.c: Scheduling destruction of SIP dialog '031b1f23085f6bef4c2f6532193aaf9c@192.168.0.4' in 32000 ms (Method: NOTIFY)
[Apr 18 11:35:37] VERBOSE[4039] chan_sip.c: 
<--- SIP read from UDP:192.168.0.4:5060 --->
NOTIFY sip:SPA400@192.168.0.24:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.4:5060;branch=z9hG4bK21c27478
From: "SPA400" <sip:SPA400@192.168.0.4>;tag=as12326f63
To: <sip:SPA400@192.168.0.24:5060>
Contact: <sip:SPA400@192.168.0.4>
Call-ID: 7172c006078006925d4dfe5541b9338a@192.168.0.4
CSeq: 352 NOTIFY
User-Agent: LINKSYS/SPA400
Event: fxo-port-state;partial;1=on,v=32
Content-Length: 0




<------------>
[Apr 18 11:35:37] VERBOSE[4039] chan_sip.c: Scheduling destruction of SIP dialog '7172c006078006925d4dfe5541b9338a@192.168.0.4' in 32000 ms (Method: NOTIFY)
[Apr 18 11:35:37] VERBOSE[4039] chan_sip.c: 
<--- SIP read from UDP:192.168.0.4:5060 --->
NOTIFY sip:SPA400@192.168.0.24:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.4:5060;branch=z9hG4bK584539eb
From: "SPA400" <sip:SPA400@192.168.0.4>;tag=as12326f63
To: <sip:SPA400@192.168.0.24:5060>
Contact: <sip:SPA400@192.168.0.4>
Call-ID: 2bb2ea1a1526b45d1d9bbb713c615c15@192.168.0.4
CSeq: 353 NOTIFY
User-Agent: LINKSYS/SPA400
Event: fxo-port-state;partial;1=na,v=0
Content-Length: 0



<------------>
[Apr 18 11:35:37] VERBOSE[4039] chan_sip.c: Scheduling destruction of SIP dialog '2bb2ea1a1526b45d1d9bbb713c615c15@192.168.0.4' in 32000 ms (Method: NOTIFY)
[Apr 18 11:35:38] VERBOSE[4039] chan_sip.c: Really destroying SIP dialog '4dbe8907696a5c3c5cf73fd56394cf27@192.168.0.4' Method: NOTIFY
[Apr 18 11:35:40] VERBOSE[4039] chan_sip.c: 
<--- SIP read from UDP:192.168.0.4:5060 --->
NOTIFY sip:SPA400@192.168.0.24:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.4:5060;branch=z9hG4bK40199d28
From: "SPA400" <sip:SPA400@192.168.0.4>;tag=as12326f63
To: <sip:SPA400@192.168.0.24:5060>
Contact: <sip:SPA400@192.168.0.4>
Call-ID: 37ae85a9537fdb137618835c6b58efde@192.168.0.4
CSeq: 354 NOTIFY
User-Agent: LINKSYS/SPA400
Event: fxo-port-state;partial;1=on,v=29
Content-Length: 0



<------------>
[Apr 18 11:35:40] VERBOSE[4039] chan_sip.c: Scheduling destruction of SIP dialog '37ae85a9537fdb137618835c6b58efde@192.168.0.4' in 32000 ms (Method: NOTIFY)
[Apr 18 11:35:41] VERBOSE[4039] chan_sip.c: 
<--- SIP read from UDP:192.168.0.4:5060 --->
NOTIFY sip:SPA400@192.168.0.24:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.4:5060;branch=z9hG4bK3b6d2101
From: "SPA400" <sip:SPA400@192.168.0.4>;tag=as12326f63
To: <sip:SPA400@192.168.0.24:5060>
Contact: <sip:SPA400@192.168.0.4>
Call-ID: 5c5c1ab42080185904e2ce4a21f5fe7b@192.168.0.4
CSeq: 355 NOTIFY
User-Agent: LINKSYS/SPA400
Event: fxo-port-state;partial;1=na,v=0
Content-Length: 0



<------------->
[Apr 18 11:35:41] VERBOSE[4039] chan_sip.c: --- (10 headers 1 lines) ---

[Apr 18 11:35:41] VERBOSE[4039] chan_sip.c: Scheduling destruction of SIP dialog '5c5c1ab42080185904e2ce4a21f5fe7b@192.168.0.4' in 32000 ms (Method: NOTIFY)
[Apr 18 11:35:42] VERBOSE[4039] chan_sip.c: Really destroying SIP dialog '79fc24b8280ca2806c7834ae501a0a34@192.168.0.4' Method: NOTIFY
[Apr 18 11:35:42] VERBOSE[4039] chan_sip.c: 
<--- SIP read from UDP:192.168.0.4:5060 --->
INVITE sip:SPA400@192.168.0.24 SIP/2.0
From: - 01538266260<sip:anonymous@localhost>;tag=400a8c0-13c4-4f8ea70e-9bdab9f1-4ac03d5c
To: <sip:01538266260@192.168.0.4>
Call-ID: 101945f0-400a8c0-13c4-4f8ea70e-9bdab9e7-3fac282e@localhost
CSeq: 1 INVITE
Via: SIP/2.0/UDP 192.168.0.4:5060;branch=z9hG4bK-4f8ea70e-9bdab9f1-37b45865
Max-Forwards: 70
Supported: replaces,timer,100rel
Contact: <sip:01538266260@192.168.0.4:5060;transport=UDP>
Content-Type: application/SDP
Content-Length: 286

v=0
o=anonymous 8647 6672 IN IP4 192.168.0.4
s=SIP Call
c=IN IP4 192.168.0.4
t=0 0
m=audio 10000 RTP/AVP 8 101 0 18
a=ptime:30
a=fmtp:101 0-15
a=fmtp:18 annexb=no
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=sendrecv
<------------->
[Apr 18 11:35:42] VERBOSE[4039] chan_sip.c: --- (11 headers 14 lines) ---
[Apr 18 11:35:42] VERBOSE[4039] chan_sip.c: Sending to 192.168.0.4:5060 (NAT)
[Apr 18 11:35:42] VERBOSE[4039] chan_sip.c: Using INVITE request as basis request - 101945f0-400a8c0-13c4-4f8ea70e-9bdab9e7-3fac282e@localhost
[Apr 18 11:35:42] VERBOSE[4039] chan_sip.c: No matching peer for 'anonymous' from '192.168.0.4:5060'
[Apr 18 11:35:42] VERBOSE[4039] netsock2.c:   == Using SIP RTP TOS bits 184
[Apr 18 11:35:42] VERBOSE[4039] netsock2.c:   == Using SIP RTP CoS mark 5
[Apr 18 11:35:42] VERBOSE[4039] chan_sip.c: Found RTP audio format 8
[Apr 18 11:35:42] VERBOSE[4039] chan_sip.c: Found RTP audio format 101
[Apr 18 11:35:42] VERBOSE[4039] chan_sip.c: Found RTP audio format 0
[Apr 18 11:35:42] VERBOSE[4039] chan_sip.c: Found RTP audio format 18
[Apr 18 11:35:42] VERBOSE[4039] chan_sip.c: Found audio description format PCMA for ID 8
[Apr 18 11:35:42] VERBOSE[4039] chan_sip.c: Found audio description format telephone-event for ID 101
[Apr 18 11:35:42] VERBOSE[4039] chan_sip.c: Found audio description format PCMU for ID 0
[Apr 18 11:35:42] VERBOSE[4039] chan_sip.c: Found audio description format G729 for ID 18
[Apr 18 11:35:42] VERBOSE[4039] chan_sip.c: Capabilities: us - 0x90e (gsm|ulaw|alaw|g726|g729), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x10c (ulaw|alaw|g729)
[Apr 18 11:35:42] VERBOSE[4039] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|)
[Apr 18 11:35:42] VERBOSE[4039] chan_sip.c: Peer audio RTP is at port 192.168.0.4:10000
[Apr 18 11:35:42] VERBOSE[4039] chan_sip.c: Looking for SPA400 in from-sip-external (domain 192.168.0.24)
[Apr 18 11:35:42] VERBOSE[4039] chan_sip.c: list_route: hop: <sip:01538266260@192.168.0.4:5060;transport=UDP>
[Apr 18 11:35:42] VERBOSE[4039] chan_sip.c: 
<--- Transmitting (NAT) to 192.168.0.4:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.0.4:5060;branch=z9hG4bK-4f8ea70e-9bdab9f1-37b45865;received=192.168.0.4;rport=5060
From: - 01538266260<sip:anonymous@localhost>;tag=400a8c0-13c4-4f8ea70e-9bdab9f1-4ac03d5c
To: <sip:01538266260@192.168.0.4>
Call-ID: 101945f0-400a8c0-13c4-4f8ea70e-9bdab9e7-3fac282e@localhost
CSeq: 1 INVITE
Server: FPBX-2.9.0(1.8.10.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Contact: <sip:SPA400@192.168.0.24:5060>
Content-Length: 0


<------------>
[Apr 18 11:35:42] VERBOSE[9782] pbx.c:     -- Executing [SPA400@from-sip-external:1] Answer("SIP/localhost-00000115", "") in new stack
[Apr 18 11:35:42] VERBOSE[9782] chan_sip.c: Audio is at 16032
[Apr 18 11:35:42] VERBOSE[9782] chan_sip.c: Adding codec 0x4 (ulaw) to SDP
[Apr 18 11:35:42] VERBOSE[9782] chan_sip.c: Adding codec 0x8 (alaw) to SDP
[Apr 18 11:35:42] VERBOSE[9782] chan_sip.c: Adding codec 0x100 (g729) to SDP
[Apr 18 11:35:42] VERBOSE[9782] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP
[Apr 18 11:35:42] VERBOSE[9782] chan_sip.c: 
<--- Reliably Transmitting (NAT) to 192.168.0.4:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.4:5060;branch=z9hG4bK-4f8ea70e-9bdab9f1-37b45865;received=192.168.0.4;rport=5060
From: - 01538266260<sip:anonymous@localhost>;tag=400a8c0-13c4-4f8ea70e-9bdab9f1-4ac03d5c
To: <sip:01538266260@192.168.0.4>;tag=as0baf1949
Call-ID: 101945f0-400a8c0-13c4-4f8ea70e-9bdab9e7-3fac282e@localhost
CSeq: 1 INVITE
Server: FPBX-2.9.0(1.8.10.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Contact: <sip:SPA400@192.168.0.24:5060>
Content-Type: application/sdp
Content-Length: 308

v=0
o=root 1258604902 1258604902 IN IP4 192.168.0.24
s=Asterisk PBX 1.8.10.0
c=IN IP4 192.168.0.24
t=0 0
m=audio 16032 RTP/AVP 0 8 18 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

<------------>
[Apr 18 11:35:42] VERBOSE[4039] chan_sip.c: 
<--- SIP read from UDP:192.168.0.4:5060 --->
ACK sip:SPA400@192.168.0.24:5060 SIP/2.0
From: <sip:anonymous@localhost>;tag=400a8c0-13c4-4f8ea70e-9bdab9f1-4ac03d5c
To: <sip:01538266260@192.168.0.4>;tag=as0baf1949
Call-ID: 101945f0-400a8c0-13c4-4f8ea70e-9bdab9e7-3fac282e@localhost
CSeq: 1 ACK
Via: SIP/2.0/UDP 192.168.0.4:5060;branch=z9hG4bK-4f8ea70e-9bdabaa5-2dd6993a
Max-Forwards: 70
Contact: <sip:01538266260@192.168.0.4:5060;transport=UDP>
Content-Length: 0

<------------->
[Apr 18 11:35:42] VERBOSE[4039] chan_sip.c: --- (9 headers 0 lines) ---
[Apr 18 11:35:42] VERBOSE[4039] chan_sip.c: 
<--- SIP read from UDP:192.168.0.4:5060 --->
NOTIFY sip:SPA400@192.168.0.24:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.4:5060;branch=z9hG4bK5b306339
From: "SPA400" <sip:SPA400@192.168.0.4>;tag=as12326f63
To: <sip:SPA400@192.168.0.24:5060>
Contact: <sip:SPA400@192.168.0.4>
Call-ID: 6f2e24af68e4308b275fc86b0868d44b@192.168.0.4
CSeq: 356 NOTIFY
User-Agent: LINKSYS/SPA400
Event: fxo-port-state;partial;1=na,v=0
Content-Length: 0



<------------->
[Apr 18 11:35:42] VERBOSE[4039] chan_sip.c: --- (10 headers 1 lines) ---


<------------>
[Apr 18 11:35:42] VERBOSE[4039] chan_sip.c: Scheduling destruction of SIP dialog '6f2e24af68e4308b275fc86b0868d44b@192.168.0.4' in 32000 ms (Method: NOTIFY)
[Apr 18 11:35:42] VERBOSE[9782] pbx.c:     -- Executing [SPA400@from-sip-external:2] Progress("SIP/localhost-00000115", "") in new stack
[Apr 18 11:35:42] VERBOSE[9782] pbx.c:     -- Executing [SPA400@from-sip-external:3] Dial("SIP/localhost-00000115", "SIP/201") in new stack
[Apr 18 11:35:42] VERBOSE[9782] netsock2.c:   == Using SIP RTP TOS bits 184
[Apr 18 11:35:42] VERBOSE[9782] netsock2.c:   == Using SIP RTP CoS mark 5
[Apr 18 11:35:42] VERBOSE[9782] app_dial.c:     -- Called SIP/201
[Apr 18 11:35:43] VERBOSE[9782] app_dial.c:     -- SIP/201-00000116 is ringing
[Apr 18 11:35:45] VERBOSE[4039] chan_sip.c: Really destroying SIP dialog '1f547f7c5e975e886ca592ea124e5a60@192.168.0.4' Method: NOTIFY
[Apr 18 11:35:46] VERBOSE[4039] chan_sip.c: Really destroying SIP dialog '222881542b0318af627fdc6412d961e8@192.168.0.4' Method: NOTIFY
[Apr 18 11:35:47] VERBOSE[9782] app_dial.c:     -- SIP/201-00000116 answered SIP/localhost-00000115
[Apr 18 11:35:47] VERBOSE[9782] rtp_engine.c:     -- Locally bridging SIP/localhost-00000115 and SIP/201-00000116
[Apr 18 11:35:47] VERBOSE[4039] chan_sip.c: Really destroying SIP dialog '4249863665e4c5d55d2760306a9eb799@192.168.0.4' Method: NOTIFY
[Apr 18 11:35:56] VERBOSE[9782] pbx.c:   == Spawn extension (from-sip-external, SPA400, 3) exited non-zero on 'SIP/localhost-00000115'
[Apr 18 11:35:56] VERBOSE[9782] chan_sip.c: Scheduling destruction of SIP dialog '101945f0-400a8c0-13c4-4f8ea70e-9bdab9e7-3fac282e@localhost' in 32000 ms (Method: ACK)
[Apr 18 11:35:56] VERBOSE[9782] chan_sip.c: set_destination: Parsing <sip:01538266260@192.168.0.4:5060;transport=UDP> for address/port to send to
[Apr 18 11:35:56] VERBOSE[9782] chan_sip.c: set_destination: set destination to 192.168.0.4:5060
[Apr 18 11:35:56] VERBOSE[9782] chan_sip.c: Reliably Transmitting (NAT) to 192.168.0.4:5060:
BYE sip:01538266260@192.168.0.4:5060;transport=UDP SIP/2.0
Via: SIP/2.0/UDP 192.168.0.24:5060;branch=z9hG4bK6e3b3c98;rport
Max-Forwards: 70
From: <sip:01538266260@192.168.0.4>;tag=as0baf1949
To: - 01538266260<sip:anonymous@localhost>;tag=400a8c0-13c4-4f8ea70e-9bdab9f1-4ac03d5c
Call-ID: 101945f0-400a8c0-13c4-4f8ea70e-9bdab9e7-3fac282e@localhost
CSeq: 102 BYE
User-Agent: FPBX-2.9.0(1.8.10.0)
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16
Content-Length: 0


---
[Apr 18 11:35:56] VERBOSE[4039] chan_sip.c: 
<--- SIP read from UDP:192.168.0.4:5060 --->
SIP/2.0 200 OK
From: <sip:01538266260@192.168.0.4>;tag=as0baf1949
To: <sip:anonymous@localhost>;tag=400a8c0-13c4-4f8ea70e-9bdab9f1-4ac03d5c
Call-ID: 101945f0-400a8c0-13c4-4f8ea70e-9bdab9e7-3fac282e@localhost
CSeq: 102 BYE
Via: SIP/2.0/UDP 192.168.0.24:5060;rport=5060;branch=z9hG4bK6e3b3c98
Supported: replaces,timer,100rel
Content-Length: 0

<------------->
[Apr 18 11:35:56] VERBOSE[4039] chan_sip.c: --- (8 headers 0 lines) ---
[Apr 18 11:35:56] VERBOSE[4039] chan_sip.c: SIP Response message for INCOMING dialog BYE arrived
[Apr 18 11:35:56] VERBOSE[4039] chan_sip.c: Really destroying SIP dialog '101945f0-400a8c0-13c4-4f8ea70e-9bdab9e7-3fac282e@localhost' Method: ACK
[Apr 18 11:35:56] VERBOSE[4039] chan_sip.c: Really destroying SIP dialog '15ee34801bae3d0c05cd76f666083eb5@192.168.0.4' Method: NOTIFY
[Apr 18 11:35:58] VERBOSE[4039] chan_sip.c: 
<--- SIP read from UDP:192.168.0.4:5060 --->
NOTIFY sip:SPA400@192.168.0.24:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.4:5060;branch=z9hG4bK07b76f30
From: "SPA400" <sip:SPA400@192.168.0.4>;tag=as12326f63
To: <sip:SPA400@192.168.0.24:5060>
Contact: <sip:SPA400@192.168.0.4>
Call-ID: 11ab46713bfbf0bf73105f0f1f50f735@192.168.0.4
CSeq: 357 NOTIFY
User-Agent: LINKSYS/SPA400
Event: fxo-port-state;partial;1=na,v=0
Content-Length: 0



<------------>
[Apr 18 11:35:58] VERBOSE[4039] chan_sip.c: Scheduling destruction of SIP dialog '11ab46713bfbf0bf73105f0f1f50f735@192.168.0.4' in 32000 ms (Method: NOTIFY)
[Apr 18 11:35:58] VERBOSE[4039] chan_sip.c: Really destroying SIP dialog '161f90791963088825435ad46e4556f5@192.168.0.4' Method: NOTIFY
[Apr 18 11:35:58] VERBOSE[4039] chan_sip.c: 
<--- SIP read from UDP:192.168.0.4:5060 --->
NOTIFY sip:SPA400@192.168.0.24:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.4:5060;branch=z9hG4bK2e05c8ea
From: "SPA400" <sip:SPA400@192.168.0.4>;tag=as12326f63
To: <sip:SPA400@192.168.0.24:5060>
Contact: <sip:SPA400@192.168.0.4>
Call-ID: 5abe183734e7b9584e85e1435fa0e681@192.168.0.4
CSeq: 358 NOTIFY
User-Agent: LINKSYS/SPA400
Event: fxo-port-state;partial;1=on,v=36
Content-Length: 0



<------------>
[Apr 18 11:35:58] VERBOSE[4039] chan_sip.c: Scheduling destruction of SIP dialog '5abe183734e7b9584e85e1435fa0e681@192.168.0.4' in 32000 ms (Method: NOTIFY)
[Apr 18 11:35:58] VERBOSE[4039] chan_sip.c: 
<--- SIP read from UDP:192.168.0.4:5060 --->
NOTIFY sip:SPA400@192.168.0.24:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.4:5060;branch=z9hG4bK56ddb7d3
From: "SPA400" <sip:SPA400@192.168.0.4>;tag=as12326f63
To: <sip:SPA400@192.168.0.24:5060>
Contact: <sip:SPA400@192.168.0.4>
Call-ID: 3a98e6cf4025ab1d320e1b0c29c70b7e@192.168.0.4
CSeq: 359 NOTIFY
User-Agent: LINKSYS/SPA400
Event: fxo-port-state;partial;1=na,v=0
Content-Length: 0



<------------>
[Apr 18 11:35:58] VERBOSE[4039] chan_sip.c: Scheduling destruction of SIP dialog '3a98e6cf4025ab1d320e1b0c29c70b7e@192.168.0.4' in 32000 ms (Method: NOTIFY)
[Apr 18 11:35:59] VERBOSE[4039] chan_sip.c: Really destroying SIP dialog '6b3e99a163754702446fe49e271db1af@127.0.0.1' Method: REGISTER
[Apr 18 11:35:59] VERBOSE[4039] chan_sip.c: Really destroying SIP dialog '5046738350c533594e64ebc5536d80d3@192.168.0.4' Method: NOTIFY
[Apr 18 11:35:59] VERBOSE[4039] chan_sip.c: 
<--- SIP read from UDP:192.168.0.4:5060 --->
NOTIFY sip:SPA400@192.168.0.24:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.4:5060;branch=z9hG4bK2909dba8
From: "SPA400" <sip:SPA400@192.168.0.4>;tag=as12326f63
To: <sip:SPA400@192.168.0.24:5060>
Contact: <sip:SPA400@192.168.0.4>
Call-ID: 596de377322fdfc933b080ab72406be8@192.168.0.4
CSeq: 360 NOTIFY
User-Agent: LINKSYS/SPA400
Event: fxo-port-state;partial;1=on,v=3
Content-Length: 0


<------------>
[Apr 18 11:35:59] VERBOSE[4039] chan_sip.c: Scheduling destruction of SIP dialog '596de377322fdfc933b080ab72406be8@192.168.0.4' in 32000 ms (Method: NOTIFY)
[Apr 18 11:35:59] VERBOSE[4039] chan_sip.c: 
<--- SIP read from UDP:192.168.0.4:5060 --->
NOTIFY sip:SPA400@192.168.0.24:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.4:5060;branch=z9hG4bK4218baa7
From: "SPA400" <sip:SPA400@192.168.0.4>;tag=as12326f63
To: <sip:SPA400@192.168.0.24:5060>
Contact: <sip:SPA400@192.168.0.4>
Call-ID: 1ba524034ccc27e42a46cf702f4cb175@192.168.0.4
CSeq: 361 NOTIFY
User-Agent: LINKSYS/SPA400
Event: fxo-port-state;partial;4=na,v=0
Content-Length: 0

<------------>
[Apr 18 11:35:59] VERBOSE[4039] chan_sip.c: Scheduling destruction of SIP dialog '1ba524034ccc27e42a46cf702f4cb175@192.168.0.4' in 32000 ms (Method: NOTIFY)
[Apr 18 11:36:00] VERBOSE[4039] chan_sip.c: 
<--- SIP read from UDP:192.168.0.4:5060 --->
NOTIFY sip:SPA400@192.168.0.24:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.4:5060;branch=z9hG4bK3c7e983c
From: "SPA400" <sip:SPA400@192.168.0.4>;tag=as12326f63
To: <sip:SPA400@192.168.0.24:5060>
Contact: <sip:SPA400@192.168.0.4>
Call-ID: 30109faa7f559afc7aaa039a75f40d0d@192.168.0.4
CSeq: 362 NOTIFY
User-Agent: LINKSYS/SPA400
Event: fxo-port-state;partial;3=na,v=0
Content-Length: 0


<------------>
[Apr 18 11:36:00] VERBOSE[4039] chan_sip.c: Scheduling destruction of SIP dialog '30109faa7f559afc7aaa039a75f40d0d@192.168.0.4' in 32000 ms (Method: NOTIFY)
[Apr 18 11:36:00] VERBOSE[4039] chan_sip.c: 
<--- SIP read from UDP:192.168.0.4:5060 --->
NOTIFY sip:SPA400@192.168.0.24:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.4:5060;branch=z9hG4bK070d0a2c
From: "SPA400" <sip:SPA400@192.168.0.4>;tag=as12326f63
To: <sip:SPA400@192.168.0.24:5060>
Contact: <sip:SPA400@192.168.0.4>
Call-ID: 0c554a0b31effdcc7a1d693b2ba64140@192.168.0.4
CSeq: 363 NOTIFY
User-Agent: LINKSYS/SPA400
Event: fxo-port-state;partial;2=na,v=0
Content-Length: 0




<------------>
[Apr 18 11:36:00] VERBOSE[4039] chan_sip.c: Scheduling destruction of SIP dialog '0c554a0b31effdcc7a1d693b2ba64140@192.168.0.4' in 32000 ms (Method: NOTIFY)
[Apr 18 11:36:01] VERBOSE[9781] asterisk.c:     -- Remote UNIX connection disconnected
[Apr 18 11:36:01] VERBOSE[4039] chan_sip.c: 
<--- SIP read from UDP:192.168.0.4:5060 --->
NOTIFY sip:SPA400@192.168.0.24:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.4:5060;branch=z9hG4bK76a91369
From: "SPA400" <sip:SPA400@192.168.0.4>;tag=as12326f63
To: <sip:SPA400@192.168.0.24:5060>
Contact: <sip:SPA400@192.168.0.4>
Call-ID: 66053ff916410d9a3141fa38262aeb16@192.168.0.4
CSeq: 364 NOTIFY
User-Agent: LINKSYS/SPA400
Event: fxo-port-state;partial;1=na,v=0
Content-Length: 0




<------------>
[Apr 18 11:36:01] VERBOSE[4039] chan_sip.c: Scheduling destruction of SIP dialog '66053ff916410d9a3141fa38262aeb16@192.168.0.4' in 32000 ms (Method: NOTIFY)
[Apr 18 11:36:03] VERBOSE[4039] chan_sip.c: Really destroying SIP dialog '0506e00e35fee63433aa6a353a25d5b1@192.168.0.4' Method: NOTIFY
[Apr 18 11:36:03] VERBOSE[4039] chan_sip.c: 
<--- SIP read from UDP:192.168.0.4:5060 --->
NOTIFY sip:SPA400@192.168.0.24:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.4:5060;branch=z9hG4bK484f28a6
From: "SPA400" <sip:SPA400@192.168.0.4>;tag=as12326f63
To: <sip:SPA400@192.168.0.24:5060>
Contact: <sip:SPA400@192.168.0.4>
Call-ID: 5b0905b64f34c6be21bd0c1d0d38e580@192.168.0.4
CSeq: 365 NOTIFY
User-Agent: LINKSYS/SPA400
Event: fxo-port-state;partial;1=on,v=-4
Content-Length: 0

<------------>
[Apr 18 11:36:03] VERBOSE[4039] chan_sip.c: Scheduling destruction of SIP dialog '5b0905b64f34c6be21bd0c1d0d38e580@192.168.0.4' in 32000 ms (Method: NOTIFY)

The failure is on the outgoing side (SIP/201), but you don’t appear to have protocol tracing enabled on that side.

Incidentally, you appear to have an explicit answer on the incoming side. That will mean the caller gets charged, even if the call fails on the outgoing side.