Spitfire Trunk issue

[IT at Work]

I have an irregular problem with a Spitifre trunk on a SARK (5.0.0.32).  The SARK web interface shows the trunk is up, but Spitfire state they are not seeing any registration requests.  This seems to happen every couple of months.

However looker at the CLI I see

Code Select Expand

sip show registry
Host                                    dnsmgr Username       Refresh State                Reg.Time
spitfiretsp.net:5060                    N      4420xxxxxxx        75 No Authentication    Tue, 14 Nov 2017 23:39:56

Any ideas why this should occur?

MTIA

[IT at Work]

I should add, setting the trunk to not active, then switching it back to active gets the trunk working again.

[sysadmin]

It's saying that a register attempt was made that didn't authorise.  I suspect you should speak to Spitfire to see what they are seeing from their end.  Are you required to register with the Spitfire softswitch?  AFAIK, they run end to end across their own network so maybe they don't require registration.   

[IT at Work]

Sorry for the late reply, I didn't subscribe to the topic.

The issue occurred again this morning (more frequent now it appears) so I was able to investigate further.  Spitfire claim that they are not receiving a registration request from the pbx.  Spitfire operate what they call a VRF - effectively they lock the SIP registration to their network, but this particular trunk runs on a (leased line) circuit we supply so Spitfire have added the IP to their VRF range.

Is there anything further I should do the next time this occurs before I disable/re-enable the trunk (which fixes the issue) to try and isolate what might be causing this.

MTIA

[sysadmin]

If Spitfire can't see a registration then it would appear that what you are sending is either incorrect or not wanted.   If it were me I would run a pcap trace or a simple sip debug from Asterisk pointing at the Spitfire IP.   Turn full logging on and email them the sip registration packets you are sending.    I think that should be sufficient to get a pointer to what is going amiss.

[IT at Work]

Nearly 3 months later this has happened again ... I'm engaging with Spitfire but they don't think it's an issue at their end.

The debug on the trunk IP shows :

Code Select Expand

Reliably Transmitting (no NAT) to 83.218.143.16:5060:
OPTIONS sip:spitfiretsp.net SIP/2.0
Via: SIP/2.0/UDP 192.168.81.200:5060;branch=z9hG4bK4285065a
Max-Forwards: 70
From: "asterisk" <sip:44xxxxxxxxxx@192.168.81.200>;tag=as3822e0a6
To: <sip:spitfiretsp.net>
Contact: <sip:44xxxxxxxxxx@192.168.81.200:5060>
Call-ID: 1e07ba343b9f86836798f2a27ef2e7db@192.168.81.200:5060
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX 11.13.1~dfsg-2+deb8u2
Date: Fri, 26 Jan 2018 10:17:06 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


---

<--- SIP read from UDP:83.218.143.16:5060 --->
SIP/2.0 202 Not understood
Via: SIP/2.0/UDP 192.168.81.200:5060;received=46.102.214.214;branch=z9hG4bK4285065a;rport=50628
From: <sip:44xxxxxxxxxx@192.168.81.200>;tag=as3822e0a6
To: <sip:spitfiretsp.net>;tag=9d9d1304547cf9dc5dd59d58f131aae1.b9a3
Call-ID: 1e07ba343b9f86836798f2a27ef2e7db@192.168.81.200:5060
CSeq: 102 OPTIONS
Content-Length: 0

<------------->
--- (7 headers 0 lines) ---
Really destroying SIP dialog '1e07ba343b9f86836798f2a27ef2e7db@192.168.81.200:5060' Method: OPTIONS

As stated previously, Spitfire state the trunk is not registered.

I did a little more digging, and am not sure if what I am seeing is correct - there seem to be 3 active channels here to Spitfire ?

Code Select Expand

sip show channels
Peer             User/ANR         Call ID          Format           Hold     Last Message    Expiry     Peer
192.168.81.46    (None)           2d000000eb59-dq  (nothing)        No       Rx: REGISTER               <guest>
83.218.143.16    44xxxxxxxxxx     b377e504-5925-1  (alaw)           No       Rx: ACK                    44203696xx
83.218.143.16    44xxxxxxxxxx     38c68dee-79fd-1  (alaw)           No       Rx: ACK                    44203696xx
83.218.143.16    44xxxxxxxxxx     71aa9a11-5485-1  (alaw)           No       Rx: ACK                    44203696xx
4 active SIP dialogs

The active channels persist even after I disabled the trunk via the web interface.

I then turned off debugging and went back into the CLI with logging on 4, and my session immediately filled with repeating scrolling output, a sample of which is

Code Select Expand

Connected to Asterisk 11.13.1~dfsg-2+deb8u2 currently running on SARK (pid = 1223)
SARK*CLI>
    -- AGI Script Executing Application: (Set) Options: (CDR(userfield)=_XXXX.)

SARK*CLI>
    -- <SIP/44203696xxxx-000008f1>AGI Script sarkhpe completed, returning 0

SARK*CLI>
    -- Executing [44203696xxxx@from-trunk:2] Set("SIP/44203696xxxx-000008f1", "parseDDI=") in new stack
    -- Executing [44203696xxxx@from-trunk:3] Goto("SIP/44203696xxxx-000008f1", "from-trunk,,1") in new stack
    -- Goto (from-trunk,44203696xxxx,1)
    -- Executing [44203696xxxx@from-trunk:1] AGI("SIP/44203696xxxx-000008f1", "sarkhpe,Inbound,_XXXX.,,") in new stack
    -- Launched AGI Script /usr/share/asterisk/agi-bin/sarkhpe

SARK*CLI>
    -- <SIP/44203696xxxx-00001743>AGI Script sarkhpe completed, returning 0

SARK*CLI>
    -- Executing [44207720xxxx@from-trunk:2] Set("SIP/44203696xxxx-00001743", "parseDDI=") in new stack
    -- Executing [44207720xxxx@from-trunk:3] Goto("SIP/44203696xxxx-00001743", "from-trunk,,1") in new stack
    -- Goto (from-trunk,44207720xxxx,1)
    -- Executing [44207720xxxx@from-trunk:1] AGI("SIP/44203696xxxx-00001743", "sarkhpe,Inbound,_XXXX.,,") in new stack
    -- Launched AGI Script /usr/share/asterisk/agi-bin/sarkhpe

SARK*CLI>
    -- <SIP/44203696xxxx-00000bbd>AGI Script sarkhpe completed, returning 0

SARK*CLI>
    -- Executing [44207720xxxx@from-trunk:2] Set("SIP/44203696xxxx-00000bbd", "parseDDI=") in new stack
    -- Executing [44207720xxxx@from-trunk:3] Goto("SIP/44203696xxxx-00000bbd", "from-trunk,,1") in new stack
    -- Goto (from-trunk,44207720xxxx,1)
    -- Executing [44207720xxxx@from-trunk:1] AGI("SIP/44203696xxxx-00000bbd", "sarkhpe,Inbound,_XXXX.,,") in new stack
    -- Launched AGI Script /usr/share/asterisk/agi-bin/sarkhpe

SARK*CLI>
    -- AGI Script Executing Application: (Set) Options: (CDR(userfield)=_XXXX.)

SARK*CLI>
    -- AGI Script Executing Application: (Set) Options: (CDR(userfield)=_XXXX.)

SARK*CLI>
    -- AGI Script Executing Application: (Set) Options: (CDR(userfield)=_XXXX.)

SARK*CLI>
    -- <SIP/44203696xxxx-000008f1>AGI Script sarkhpe completed, returning 0

SARK*CLI>
    -- Executing [44203696xxxx@from-trunk:2] Set("SIP/44203696xxxx-000008f1", "parseDDI=") in new stack
    -- Executing [44203696xxxx@from-trunk:3] Goto("SIP/44203696xxxx-000008f1", "from-trunk,,1") in new stack
    -- Goto (from-trunk,44203696xxxx,1)
    -- Executing [44203696xxxx@from-trunk:1] AGI("SIP/44203696xxxx-000008f1", "sarkhpe,Inbound,_XXXX.,,") in new stack
    -- Launched AGI Script /usr/share/asterisk/agi-bin/sarkhpe

SARK*CLI>
    -- <SIP/44203696xxxx-00001743>AGI Script sarkhpe completed, returning 0

SARK*CLI>
    -- Executing [44207720xxxx@from-trunk:2] Set("SIP/44203696xxxx-00001743", "parseDDI=") in new stack
    -- Executing [44207720xxxx@from-trunk:3] Goto("SIP/44203696xxxx-00001743", "from-trunk,,1") in new stack
    -- Goto (from-trunk,44207720xxxx,1)
    -- Executing [44207720xxxx@from-trunk:1] AGI("SIP/44203696xxxx-00001743", "sarkhpe,Inbound,_XXXX.,,") in new stack
    -- Launched AGI Script /usr/share/asterisk/agi-bin/sarkhpe

SARK*CLI>
    -- <SIP/44203696xxxx-00000bbd>AGI Script sarkhpe completed, returning 0

SARK*CLI>
    -- Executing [44207720xxxx@from-trunk:2] Set("SIP/44203696xxxx-00000bbd", "parseDDI=") in new stack
    -- Executing [44207720xxxx@from-trunk:3] Goto("SIP/44203696xxxx-00000bbd", "from-trunk,,1") in new stack
    -- Goto (from-trunk,44207720xxxx,1)
    -- Executing [44207720xxxx@from-trunk:1] AGI("SIP/44203696xxxx-00000bbd", "sarkhpe,Inbound,_XXXX.,,") in new stack
    -- Launched AGI Script /usr/share/asterisk/agi-bin/sarkhpe

SARK*CLI>
    -- AGI Script Executing Application: (Set) Options: (CDR(userfield)=_XXXX.)

SARK*CLI>
    -- AGI Script Executing Application: (Set) Options: (CDR(userfield)=_XXXX.)

SARK*CLI>
    -- AGI Script Executing Application: (Set) Options: (CDR(userfield)=_XXXX.)

SARK*CLI>
    -- <SIP/44203696xxxx-000008f1>AGI Script sarkhpe completed, returning 0

SARK*CLI>
    -- Executing [44203696xxxx@from-trunk:2] Set("SIP/44203696xxxx-000008f1", "parseDDI=") in new stack
    -- Executing [44203696xxxx@from-trunk:3] Goto("SIP/44203696xxxx-000008f1", "from-trunk,,1") in new stack
    -- Goto (from-trunk,44203696xxxx,1)
    -- Executing [44203696xxxx@from-trunk:1] AGI("SIP/44203696xxxx-000008f1", "sarkhpe,Inbound,_XXXX.,,") in new stack
    -- Launched AGI Script /usr/share/asterisk/agi-bin/sarkhpe

SARK*CLI>
    -- <SIP/44203696xxxx-00001743>AGI Script sarkhpe completed, returning 0

SARK*CLI>
    -- Executing [44207720xxxx@from-trunk:2] Set("SIP/44203696xxxx-00001743", "parseDDI=") in new stack
    -- Executing [44207720xxxx@from-trunk:3] Goto("SIP/44203696xxxx-00001743", "from-trunk,,1") in new stack
    -- Goto (from-trunk,44207720xxxx,1)
    -- Executing [44207720xxxx@from-trunk:1] AGI("SIP/44203696xxxx-00001743", "sarkhpe,Inbound,_XXXX.,,") in new stack
    -- Launched AGI Script /usr/share/asterisk/agi-bin/sarkhpe

SARK*CLI>
    -- <SIP/44203696xxxx-00000bbd>AGI Script sarkhpe completed, returning 0

SARK*CLI>
    -- Executing [44207720xxxx@from-trunk:2] Set("SIP/44203696xxxx-00000bbd", "parseDDI=") in new stack
    -- Executing [44207720xxxx@from-trunk:3] Goto("SIP/44203696xxxx-00000bbd", "from-trunk,,1") in new stack
    -- Goto (from-trunk,44207720xxxx,1)
    -- Executing [44207720xxxx@from-trunk:1] AGI("SIP/44203696xxxx-00000bbd", "sarkhpe,Inbound,_XXXX.,,") in new stack
    -- Launched AGI Script /usr/share/asterisk/agi-bin/sarkhpe

SARK*CLI>
    -- AGI Script Executing Application: (Set) Options: (CDR(userfield)=_XXXX.)

SARK*CLI>
    -- AGI Script Executing Application: (Set) Options: (CDR(userfield)=_XXXX.)

SARK*CLI>
    -- AGI Script Executing Application: (Set) Options: (CDR(userfield)=_XXXX.)

Obviously I'm not an expert, but is it possible there is some sort of issue occurring with the trunk config, causing the SARK to get stuck in a loop?

I did a graceful restart of asterisk which stopped the output cycling on the screen, re-enabled the trunk and everything appears to be fine now for the time being.

[sysadmin]

There appear to be two different things going on here.

The first trace shows Asterisk sending an options packet to Spitfire and Spitfire returning a 202.   Ordinarily, if you have qualify=(yes|milliseconds) in the trunk, Asterisk will send an options packet every 60 seconds, kind of like a ping, to check if the circuit is up and responding.  Asterisk will consider the circuit down if it doesn't respond in {qualify} milliseconds.    I'm not sure what Asterisk decides if the far-end is returning SIP 202, which according to the RFC means the request was accepted for processing but not completed.  You would need to ask Spitfire why they are returning a 202.  It may be that they believe you aren't registered.   Usually, Asterisk will continue to attempt registration if a registration doesn't complete or respond so, as I said above, I think you would need to run a full PCAP trace to see how the two partners are getting into that state.  You could try registering more often but that would really be a bandaid rather than a solution.

The second issue you show does look a little like a loop.   Spitfire has its own in-house softswitch.  From memory, the original switch was based upon the old Snom pbx (Snom One) but I think they may have replaced that in part or in whole, with something else. Anyhow, they send the DDI in a different place to other carriers.   Asterisk expects the DDI to be in the Request-Line-URI e.g. INVITE sip:somenumber@someaddress.    Unfortunately, Spitfire doesn't put it there so we have to grab it from the TO header.   Thats what the parseDDI lines are doing in your console trace.   Once the DDI is found, the call is restarted with the scavenged DDI.   In your example the DDI is  44207720xxxx.   Anyhow, you don't have a DDI in your inbound routing which exactly matches the DDI and Asterisk is matching it against a routing of _XXXX.   Where does _XXXX. route the call in yourPBX?  (look in inbound routing).   Once we know that we may understand better what is happening.

You can ask SARK to give you more debugging information.  Run this command at the asterisk console

dialplan set global DEBUG ON

It will give you a ton of stuff about what SARK is doing with the call.

To turn it off again do

dialplan set global DEBUG ""

That's 2 double quotes.

     

[IT at Work]

Did you just say Snom ONE ... that pile of steaming $*%^ !!! I've still got one of those running at a clients and it gives me nothing but trouble!

Thanks for all that ... Spitfire's response so far is

... engineers have advised that we do not accept OPTION messages so the response you are seeing is correct - this should not stop any functionality of the SIP trunk however.

I've gone back to them asking for their SARK engineer to look at this (after all don't they still supply them?)