Topic: Call to Cisco SPA 3102 affected from asterisk on second call attempt

[jufra]

Hi devs,

We see an issue on two installations of Sail (both ver. 3.1.0-128, asterisk 1.8.5.0). It is a very simple setup, and I have simplified it even more to get to the bottom of the issue. So here is the scenario:

We have a Cisco SPA3102 hooked up to the SAIL server to connect a landline to the system. It all works, can receive calls, make outgoing calls.

Now, the following problem happens:

I call an outgoing number, say a mobile number. The call goes out on the SPA, and is up and running. Now I dial a landline number which is routed to the SPA as well. As expected, the SPA reports that it is busy. NOw something weird happens after we hang up the second call. The asterisk sends an invite to itself via the SPA, and out of the blue we get an inbound call from the SPA.
In some cases this causes the original call (call to the mobile number) to drop, sometimes it leads to conference calls which were not intended, or it goes to voicemail or all sorts of trouble.

Even though it looks like this is coming from the SPA, I think it is triggered from asterisk... but why? Where does the INVITE come from, ie, why does asterisk send it?

Relevant bit in the trace is this (192.168.30.1 is the asterisk server, 192.168.30.10 is the SPA) Also made a few comments in the trace below in regards to the numbers:

Code: [Select]

  == Using SIP RTP CoS mark 5
    -- Executing [04xxxxxxxx@internal:1] AGI("SIP/3040-0000008c", "sarkhpe,OutCos,04xxxxxxxx") in new stack
    -- Launched AGI Script /var/lib/asterisk/agi-bin/sarkhpe
    -- <SIP/3040-0000008c>AGI Script sarkhpe completed, returning 0
    -- Executing [04xxxxxxxx@3040opencos:1] AGI("SIP/3040-0000008c", "sarkhpe,OutCluster,04xxxxxxxx") in new stack
    -- Launched AGI Script /var/lib/asterisk/agi-bin/sarkhpe
    -- AGI Script Executing Application: (Set) Options: (CDR(accountcode)=default)
    -- <SIP/3040-0000008c>AGI Script sarkhpe completed, returning 0
    -- Executing [04xxxxxxxx@qrxvtmny:1] AGI("SIP/3040-0000008c", "sarkhpe,OutRoute,Optus") in new stack
    -- Launched AGI Script /var/lib/asterisk/agi-bin/sarkhpe
    -- AGI Script Executing Application: (Set) Options: (TIMEOUT(absolute)=14400)
Channel will hangup at 2013-05-16 21:05:02.869 EST.
    -- AGI Script Executing Application: (Dial) Options: (SIP/04xxxxxxxx@peer5030,,T)
  == Using SIP RTP CoS mark 5
Audio is at 5060
Adding codec 0x4 (ulaw) to SDP
Adding codec 0x2 (gsm) to SDP
Adding codec 0x8 (alaw) to SDP
Adding codec 0x800000000000 (testlaw) to SDP
Adding non-codec 0x1 (telephone-event) to SDP
Reliably Transmitting (no NAT) to 192.168.30.10:5060:
INVITE sip:04xxxxxxxx@192.168.30.10 SIP/2.0
Via: SIP/2.0/UDP 192.168.30.1:5060;branch=z9hG4bK6eb49bc4
Max-Forwards: 70
From: "3040" <sip:3040@192.168.30.1>;tag=as4e36ee05
To: <sip:04xxxxxxxx@192.168.30.10>
Contact: <sip:3040@192.168.30.1:5060>
Call-ID: 0c44236058a27487433b2c6d5543b06c@192.168.30.1:5060
CSeq: 102 INVITE
User-Agent: Asterisk PBX 1.8.5.0
Date: Thu, 16 May 2013 07:05:02 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Type: application/sdp
Content-Length: 281

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

---
    -- Called SIP/04xxxxxxxx@peer5030

<--- SIP read from UDP:192.168.30.10:5060 --->
SIP/2.0 100 Trying
To: <sip:04xxxxxxxx@192.168.30.10>
From: "3040" <sip:3040@192.168.30.1>;tag=as4e36ee05
Call-ID: 0c44236058a27487433b2c6d5543b06c@192.168.30.1:5060
CSeq: 102 INVITE
Via: SIP/2.0/UDP 192.168.30.1:5060;branch=z9hG4bK6eb49bc4
Server: Linksys/SPA3102-5.2.13(GW002)
Content-Length: 0

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


CALL UP to mobile (04xxxxx)

NOW call to another landline number (07xxxxx):
 == Using SIP RTP CoS mark 5
    -- Executing [07xxxxxxxx@internal:1] AGI("SIP/3037-0000008f", "sarkhpe,OutCos,07xxxxxxxx") in new stack
    -- Launched AGI Script /var/lib/asterisk/agi-bin/sarkhpe
    -- <SIP/3037-0000008f>AGI Script sarkhpe completed, returning 0
    -- Executing [07xxxxxxxx@3037opencos:1] AGI("SIP/3037-0000008f", "sarkhpe,OutCluster,07xxxxxxxx") in new stack
    -- Launched AGI Script /var/lib/asterisk/agi-bin/sarkhpe
    -- AGI Script Executing Application: (Set) Options: (CDR(accountcode)=default)
    -- <SIP/3037-0000008f>AGI Script sarkhpe completed, returning 0
    -- Executing [07xxxxxxxx@qrxvtmny:1] AGI("SIP/3037-0000008f", "sarkhpe,OutRoute,Optus") in new stack
    -- Launched AGI Script /var/lib/asterisk/agi-bin/sarkhpe
    -- AGI Script Executing Application: (Set) Options: (TIMEOUT(absolute)=14400)
Channel will hangup at 2013-05-16 21:05:31.504 EST.
    -- AGI Script Executing Application: (Dial) Options: (SIP/07xxxxxxxx@peer5030,,T)
  == Using SIP RTP CoS mark 5
Audio is at 5060
Adding codec 0x4 (ulaw) to SDP
Adding codec 0x2 (gsm) to SDP
Adding codec 0x8 (alaw) to SDP
Adding codec 0x800000000000 (testlaw) to SDP
Adding non-codec 0x1 (telephone-event) to SDP
Reliably Transmitting (no NAT) to 192.168.30.10:5060:
INVITE sip:07xxxxxxxx@192.168.30.10 SIP/2.0
Via: SIP/2.0/UDP 192.168.30.1:5060;branch=z9hG4bK3226d026
Max-Forwards: 70
From: "3037" <sip:3037@192.168.30.1>;tag=as25a91317
To: <sip:07xxxxxxxx@192.168.30.10>
Contact: <sip:3037@192.168.30.1:5060>
Call-ID: 46263ad356467d35704b278051aebe39@192.168.30.1:5060
CSeq: 102 INVITE
User-Agent: Asterisk PBX 1.8.5.0
Date: Thu, 16 May 2013 07:05:31 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Type: application/sdp
Content-Length: 283

This ends up as busy:
   -- SIP/peer5030-00000090 is circuit-busy
  == Everyone is busy/congested at this time (1:0/1/0)
    -- AGI Script Executing Application: (Playback) Options: (beep)
Really destroying SIP dialog '46263ad356467d35704b278051aebe39@192.168.30.1:5060' Method: INVITE
    -- <SIP/3037-0000008f> Playing 'beep.gsm' (language 'en-gb')
    -- AGI Script Executing Application: (Playtones) Options: (congestion)
    -- AGI Script Executing Application: (Congestion) Options: ()
    -- <SIP/3037-0000008f>AGI Script sarkhpe completed, returning 4
  == Spawn extension (qrxvtmny, 07xxxxxxxx, 1) exited non-zero on 'SIP/3037-0000008f'
    -- Executing [h@qrxvtmny:1] Hangup("SIP/3037-0000008f", "") in new stack

Continued in next post


[jufra]

Now, upon hangup of the unsuccessful call, we get this invite, which I'm not sure what it is (BTW, the 613xxx number is the SPA trunknumber):

Code: [Select]

<--- SIP read from UDP:192.168.30.10:5060 --->
INVITE sip:613xxxxxxxx@192.168.30.1 SIP/2.0
Via: SIP/2.0/UDP 192.168.30.10:5060;branch=z9hG4bK-6d5e1f1a
From: 613xxxxxxxx <sip:04xxxxxxxx@192.168.30.1>;tag=76178c64dce01e1o1
To: <sip:613xxxxxxxx@192.168.30.1>
Remote-Party-ID: 613xxxxxxxx <sip:04xxxxxxxx@192.168.30.1>;screen=yes;party=calling
Call-ID: 59ff04e0-d96a8395@192.168.30.10
CSeq: 101 INVITE
Max-Forwards: 70
Contact: 613xxxxxxxx <sip:04xxxxxxxx@192.168.30.10:5060>
Expires: 240
User-Agent: Linksys/SPA3102-5.2.13(GW002)
Content-Length: 261
Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
Supported: x-sipura, replaces
Content-Type: application/sdp

v=0
o=- 190025846 190025846 IN IP4 192.168.30.10
s=-
c=IN IP4 192.168.30.10
t=0 0
m=audio 16460 RTP/AVP 0 100 101
a=rtpmap:0 PCMU/8000
a=rtpmap:100 NSE/8000
a=fmtp:100 192-193
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:30
a=sendrecv
<------------->
--- (15 headers 13 lines) ---
Sending to 192.168.30.10:5060 (no NAT)
Using INVITE request as basis request - 59ff04e0-d96a8395@192.168.30.10
Found peer 'peer5030' for '04xxxxxxxx' from 192.168.30.10:5060
  == Using SIP RTP CoS mark 5
Found RTP audio format 0
Found RTP audio format 100
Found RTP audio format 101
Found audio description format PCMU for ID 0
Found unknown media description format NSE for ID 100
Found audio description format telephone-event for ID 101
Capabilities: us - 0x80000008000e (gsm|ulaw|alaw|h263|testlaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x4 (ulaw)
Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|)
Peer audio RTP is at port 192.168.30.10:16460
Looking for 613xxxxxxxx in mainmenu (domain 192.168.30.1)
list_route: hop: <sip:04xxxxxxxx@192.168.30.10:5060>



And it leads to an inbound call from the SPA:

<--- Transmitting (no NAT) to 192.168.30.10:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.30.10:5060;branch=z9hG4bK-6d5e1f1a;received=192.168.30.10
From: 613xxxxxxxx <sip:04xxxxxxxx@192.168.30.1>;tag=76178c64dce01e1o1
To: <sip:613xxxxxxxx@192.168.30.1>
Call-ID: 59ff04e0-d96a8395@192.168.30.10
CSeq: 101 INVITE
Server: Asterisk PBX 1.8.5.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Contact: <sip:613xxxxxxxx@192.168.30.1:5060>
Content-Length: 0


<------------>
    -- Executing [613xxxxxxxx@mainmenu:1] AGI("SIP/peer5030-00000091", "sarkhpe,Inbound,613xxxxxxxx") in new stack
    -- Launched AGI Script /var/lib/asterisk/agi-bin/sarkhpe
    -- AGI Script Executing Application: (Set) Options: (CDR(userfield)=613xxxxxxxx)
    -- AGI Script Executing Application: (SetCallerPres) Options: (allowed)
    -- <SIP/peer5030-00000091>AGI Script sarkhpe completed, returning 0
    -- Executing [3080@extensions:1] AGI("SIP/peer5030-00000091", "sarkhpe,Alias,SIP/3050 SIP/3040 SIP/3037,3080") in new stack
    -- Launched AGI Script /var/lib/asterisk/agi-bin/sarkhpe
    -- AGI Script Executing Application: (Dial) Options: (SIP/3050&SIP/3040&SIP/3037,20,)
  == Using SIP RTP CoS mark 5
    -- Called SIP/3050
  == Using SIP RTP CoS mark 5
    -- Called SIP/3040
  == Using SIP RTP CoS mark 5
    -- Called SIP/3037
    -- SIP/3050-00000092 connected line has changed. Saving it until answer for SIP/peer5030-00000091
    -- SIP/3040-00000093 connected line has changed. Saving it until answer for SIP/peer5030-00000091
    -- SIP/3037-00000094 connected line has changed. Saving it until answer for SIP/peer5030-00000091
    -- SIP/3037-00000094 is ringing

<--- Transmitting (no NAT) to 192.168.30.10:5060 --->
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 192.168.30.10:5060;branch=z9hG4bK-6d5e1f1a;received=192.168.30.10
From: 613xxxxxxxx <sip:04xxxxxxxx@192.168.30.1>;tag=76178c64dce01e1o1
To: <sip:613xxxxxxxx@192.168.30.1>;tag=as368a31f2
Call-ID: 59ff04e0-d96a8395@192.168.30.10
CSeq: 101 INVITE
Server: Asterisk PBX 1.8.5.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Contact: <sip:613xxxxxxxx@192.168.30.1:5060>
Content-Length: 0


<------------>
    -- SIP/3050-00000092 is ringing
    -- Got SIP response 486 "Busy Here" back from 192.168.30.150:5060
    -- SIP/3040-00000093 is busy
    -- Got SIP response 486 "Busy" back from 192.168.30.206:5060
    -- SIP/3037-00000094 is busy
    -- Executing [h@qrxvtmny:1] Hangup("SIP/3040-0000008c", "") in new stack
  == Spawn extension (qrxvtmny, h, 1) exited non-zero on 'SIP/3040-0000008c'
Scheduling destruction of SIP dialog '0c44236058a27487433b2c6d5543b06c@192.168.30.1:5060' in 6400 ms (Method: INVITE)
set_destination: Parsing <sip:04xxxxxxxx@192.168.30.10:5060> for address/port to send to
set_destination: set destination to 192.168.30.10:5060
Reliably Transmitting (no NAT) to 192.168.30.10:5060:
BYE sip:04xxxxxxxx@192.168.30.10:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.30.1:5060;branch=z9hG4bK2c4d1229
Max-Forwards: 70
From: "3040" <sip:3040@192.168.30.1>;tag=as4e36ee05
To: <sip:04xxxxxxxx@192.168.30.10>;tag=ee98b1813ea740d6i1
Call-ID: 0c44236058a27487433b2c6d5543b06c@192.168.30.1:5060
CSeq: 103 BYE
User-Agent: Asterisk PBX 1.8.5.0
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16
Content-Length: 0


So this is the problem, sometimes, as I mentioned before, we get a caonference call, where I can hear two calls, but not my original partner, or similar things...

Is this related to some DISA setting in the system (other than the extensions and the trunks there's nothing else setup on this system)??

Thanks in adnvance
Cheers
Frank

[jufra]

Hi all,

I'm assuming that no one has encountered a similar problem like we are facing? We are really out of answers and scratching our heads, as the issue is still continuing to happen.
Very grateful for any clues
Thanks
Frank

[SARK devs]

Hi there

The invite you show is originating from the SPA. It just looks like a regular inbound call and Asterisk is treating it as such.  I can't see anything in the trace you've posted to suggest Asterisk is causing this invite to happen.  Do you have a more comprehensive trace?   

Kind Regards

S

   

[jufra]

Thanks S for your reply, much appreciated.
To me it looked like the invite was coming from the asterisk because it says
From: 613xxxxxxxx <sip:04xxxxxxxx@192.168.30.1>;tag=76178c64dce01e1o1
(the server), but due to my lack of knowledge on these things I of course accept your assessment.

Please let me know what you would like traced, I can reproduce this issue easily, it happens everytime I call the SPA twice...

I've also logged a case with Cisco Small Business Support and getting them to look at it. I found an old case that describes the problem
https://supportforums.cisco.com/thread/2083873
Our SW version is much higher (5.2.13), but it still seems to happen.

It seems though that it really is an issue on the SPA side, but once again, more than happy to trace more and post it here. Just let me know what exactly you want traced...

Cheers
Frank

[SARK devs]

Hi

If you are satisfied that the issue lies with the SPA then I don't require any further trace. I wanted to prove/disprove whether Asterisk was involved in starting the event which is causing your problem.  From what I can see, I don't think it is but please come back to the thread if you think it may be.   

Kind Regards

S

[jufra]

Hi S, thanks again, I had involved Cisco support before and they suspected it to be an asterisk problem, that's why I posted here. So just to be sure, I'd like to have it 100% clear that it is the SPA that's causing the problem. I'll see what their support now says in light of the forum post I mentioned below. I'll come back here if they want more proof...

Thanks
Frank