[asterisk-dev] SIP: INFO before answer causes disconnect

Alan Ferrency alan at pair.com
Fri Mar 31 15:10:25 MST 2006 

Hi. We have an odd problem with incoming SIP calls. No one had anything
to say about it on asterisk-users, so I figured someone here might be
able to help.

Basically: is this a known bug, or should I submit it? Can anyone else
reproduce it? I didn't find anything completely appropriate in Mantis,
other than one other "early dialog" SIP bug which wasn't the same. But
it seems like it would be easy enough to reproduce that if it wasn't
just my problem, someone would've seen it before.

I have attached a SIP debug log, with some asterisk verbosity,
demonstrating the problem.

The problem manifests itself with these symptoms:

- an internal SIP extension receives a call from our PRI
- the SIP phone answers the call
- after approximately 20 seconds, the PRI caller is sent to
  voicemail, and the internal extension is hung up on

This seemed to happen only randomly, but I figured out how to reproduce
it. We are using SIP INFO for DTMF. The problem occurs if the PRI caller
enters a DTMF tone after the SIP invite was sent to the SIP phone, but
before the SIP phone answers.

In this case, the SIP phone responds to the INFO packet immediately,
before the call is answered. Then, when the call is answered, the phone
responds to the initial INVITE, and Asterisk sends an ACK for the INVITE.

However, the phone never receives an ACK for the INFO response it sent.
The phone doesn't care much about this lack of ACK, but it looks like
Asterisk didn't see the INFO response. It reports:

@Scheduling destruction of call '1536d1554749f3957bdfebb548bcf9b7 at 10.11.220.1' in 15000 ms

And then, it sends a CANCEL packet to the SIP phone, with the same call
sequence number as the initial INFO SIP packet. The call then seems to
progress to the next priority in the dial plan, and is sent to
voicemail.

The phone rejects the CANCEL packet with an Internal Server Error, but I
don't think that's the problem here: the call has already gone to
voicemail before the internal server error is received.

I have verified that this is only a problem for PRI->SIP calls.
SIP->SIP calls do not generate DTMF INFO packets prior to the call
being answered.


A complete SIP debug log (with some console verbosity as well) follows.

Vital stats:
- Asterisk 1.2.3
- Sipura SPA-841, SPA-941 phones
- Fedora core 3

Thank you very much for your help.

Alan Ferrency
pair Networks, Inc.
alan at pair.com


------------------- SIP DEBUG LOG ---------------------

    -- Executing NoOp("Zap/3-1", "Dialing staff extension sip/sip_alan by XXXXXXXXXX") in new stack
    -- Executing Dial("Zap/3-1", "sip/sip_alan|20|o") in new stack
We're at 10.11.220.1 port 13296
Adding codec 0x4 (ulaw) to SDP
13 headers, 8 lines
Reliably Transmitting (no NAT) to 10.11.220.128:5060:
INVITE sip:sip_alan at alan.phone SIP/2.0
Via: SIP/2.0/UDP 10.11.220.1:5060;branch=z9hG4bK14f2d730;rport
From: "XXXXXXXXXX" <sip:XXXXXXXXXX at 10.11.220.1>;tag=as44f0e411
To: <sip:sip_alan at alan.phone>
Contact: <sip:XXXXXXXXXX at 10.11.220.1>
Call-ID: 1536d1554749f3957bdfebb548bcf9b7 at 10.11.220.1
CSeq: 102 INVITE
User-Agent: Asterisk PBX
Max-Forwards: 70
Date: Thu, 30 Mar 2006 15:48:08 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Content-Type: application/sdp
Content-Length: 156

v=0
o=root 1497 1497 IN IP4 10.11.220.1
s=session
c=IN IP4 10.11.220.1
t=0 0
m=audio 13296 RTP/AVP 0
a=rtpmap:0 PCMU/8000
a=silenceSupp:off - - - -

---
    -- Called sip_alan

<-- SIP read from 10.11.220.128:5060:
SIP/2.0 100 Trying
To: <sip:sip_alan at alan.phone>
From: "XXXXXXXXXX" <sip:XXXXXXXXXX at 10.11.220.1>;tag=as44f0e411
Call-ID: 1536d1554749f3957bdfebb548bcf9b7 at 10.11.220.1
CSeq: 102 INVITE
Via: SIP/2.0/UDP 10.11.220.1:5060;branch=z9hG4bK14f2d730
Server: Sipura/SPA941-4.1.8
Content-Length: 0


--- (8 headers 0 lines)---

<-- SIP read from 10.11.220.128:5060:
SIP/2.0 180 Ringing
To: <sip:sip_alan at alan.phone>;tag=18a7e97964d74b16i0
From: "XXXXXXXXXX" <sip:XXXXXXXXXX at 10.11.220.1>;tag=as44f0e411
Call-ID: 1536d1554749f3957bdfebb548bcf9b7 at 10.11.220.1
CSeq: 102 INVITE
Via: SIP/2.0/UDP 10.11.220.1:5060;branch=z9hG4bK14f2d730
Server: Sipura/SPA941-4.1.8
Content-Length: 0


--- (8 headers 0 lines)---

    -- SIP/sip_alan-03af is ringing
* DTMF-relay event received: #

Reliably Transmitting (no NAT) to 10.11.220.128:5060:
INFO sip:sip_alan at alan.phone SIP/2.0
Via: SIP/2.0/UDP 10.11.220.1:5060;branch=z9hG4bK122884cb;rport
From: "XXXXXXXXXX" <sip:XXXXXXXXXX at 10.11.220.1>;tag=as44f0e411
To: <sip:sip_alan at alan.phone>;tag=18a7e97964d74b16i0
Contact: <sip:XXXXXXXXXX at 10.11.220.1>
Call-ID: 1536d1554749f3957bdfebb548bcf9b7 at 10.11.220.1
CSeq: 103 INFO
User-Agent: Asterisk PBX
Max-Forwards: 70
Content-Type: application/dtmf-relay
Content-Length: 24

Signal=#
Duration=250

---

<-- SIP read from 10.11.220.128:5060:
SIP/2.0 200 OK
To: <sip:sip_alan at alan.phone>;tag=18a7e97964d74b16i0
From: "XXXXXXXXXX" <sip:XXXXXXXXXX at 10.11.220.1>;tag=as44f0e411
Call-ID: 1536d1554749f3957bdfebb548bcf9b7 at 10.11.220.1
CSeq: 103 INFO
Via: SIP/2.0/UDP 10.11.220.1:5060;branch=z9hG4bK122884cb
Server: Sipura/SPA941-4.1.8
Content-Length: 0


 --- (8 headers 0 lines)---

<-- SIP read from 10.11.220.128:5060:
SIP/2.0 200 OK
To: <sip:sip_alan at alan.phone>;tag=18a7e97964d74b16i0
From: "XXXXXXXXXX" <sip:XXXXXXXXXX at 10.11.220.1>;tag=as44f0e411
Call-ID: 1536d1554749f3957bdfebb548bcf9b7 at 10.11.220.1
CSeq: 102 INVITE
Via: SIP/2.0/UDP 10.11.220.1:5060;branch=z9hG4bK14f2d730
Contact: "Alan Ferrency" <sip:sip_alan at 10.11.220.128:5060>
Server: Sipura/SPA941-4.1.8
Content-Length: 210
Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
Content-Type: application/sdp

v=0
o=- 6691772 6691772 IN IP4 10.11.220.128
s=-
c=IN IP4 10.11.220.128
t=0 0
m=audio 16444 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=sendrecv

--- (11 headers 11 lines)---
Found RTP audio format 0
Found RTP audio format 101
Peer audio RTP is at port 10.11.220.128:16444
Found description format PCMU
Found description format telephone-event
Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw)
Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event)
list_route: hop: <sip:sip_alan at 10.11.220.128:5060>
set_destination: Parsing <sip:sip_alan at 10.11.220.128:5060> for address/port to send to
set_destination: set destination to 10.11.220.128, port 5060
Transmitting (no NAT) to 10.11.220.128:5060:
ACK sip:sip_alan at 10.11.220.128:5060 SIP/2.0
Via: SIP/2.0/UDP 10.11.220.1:5060;branch=z9hG4bK69c4c2a2;rport
From: "XXXXXXXXXX" <sip:XXXXXXXXXX at 10.11.220.1>;tag=as44f0e411
To: <sip:sip_alan at alan.phone>;tag=18a7e97964d74b16i0
Contact: <sip:XXXXXXXXXX at 10.11.220.1>
Call-ID: 1536d1554749f3957bdfebb548bcf9b7 at 10.11.220.1
CSeq: 102 ACK
User-Agent: Asterisk PBX
Max-Forwards: 70
Content-Length: 0


---
    -- Nobody picked up in 20000 ms
set_destination: Parsing <sip:sip_alan at 10.11.220.128:5060> for address/port to send to
set_destination: set destination to 10.11.220.128, port 5060
Reliably Transmitting (no NAT) to 10.11.220.128:5060:
CANCEL sip:sip_alan at alan.phone SIP/2.0
Via: SIP/2.0/UDP 10.11.220.1:5060;branch=z9hG4bK69c4c2a2;rport
From: "XXXXXXXXXX" <sip:XXXXXXXXXX at 10.11.220.1>;tag=as44f0e411
To: <sip:sip_alan at alan.phone>
Contact: <sip:XXXXXXXXXX at 10.11.220.1>
Call-ID: 1536d1554749f3957bdfebb548bcf9b7 at 10.11.220.1
CSeq: 103 CANCEL
User-Agent: Asterisk PBX
Max-Forwards: 70
Content-Length: 0


---
Scheduling destruction of call '1536d1554749f3957bdfebb548bcf9b7 at 10.11.220.1' in 15000 ms
    -- Executing VoiceMail("Zap/3-1", "u828") in new stack

<-- SIP read from 10.11.220.128:5060:
SIP/2.0 500 Internal Server Error
To: <sip:sip_alan at alan.phone>;tag=18a7e97964d74b16i0
From: "XXXXXXXXXX" <sip:XXXXXXXXXX at 10.11.220.1>;tag=as44f0e411
Call-ID: 1536d1554749f3957bdfebb548bcf9b7 at 10.11.220.1
CSeq: 103 CANCEL
Via: SIP/2.0/UDP 10.11.220.1:5060;branch=z9hG4bK69c4c2a2
Server: Sipura/SPA941-4.1.8
Content-Length: 0


--- (8 headers 0 lines)---
    -- Got SIP response 500 "Internal Server Error" back from 10.11.220.128
Destroying call '1536d1554749f3957bdfebb548bcf9b7 at 10.11.220.1'
marvin*CLI>     -- Playing '/var/spool/asterisk/voicemail/default/828/unavail' (language 'en')
marvin*CLI>     -- Playing 'vm-intro' (language 'en')

<-- SIP read from 10.11.220.128:5060:
BYE sip:XXXXXXXXXX at 10.11.220.1 SIP/2.0
Via: SIP/2.0/UDP 10.11.220.128:5060;branch=z9hG4bK-5f8f65f4
From: <sip:sip_alan at alan.phone>;tag=18a7e97964d74b16i0
To: "XXXXXXXXXX" <sip:XXXXXXXXXX at 10.11.220.1>;tag=as44f0e411
Call-ID: 1536d1554749f3957bdfebb548bcf9b7 at 10.11.220.1
CSeq: 101 BYE
Max-Forwards: 70
User-Agent: Sipura/SPA941-4.1.8
Content-Length: 0


--- (9 headers 0 lines)---
Sending to 10.11.220.128 : 5060 (non-NAT)
Transmitting (no NAT) to 10.11.220.128:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.11.220.128:5060;branch=z9hG4bK-5f8f65f4;received=10.11.220.128
From: <sip:sip_alan at alan.phone>;tag=18a7e97964d74b16i0
To: "XXXXXXXXXX" <sip:XXXXXXXXXX at 10.11.220.1>;tag=as44f0e411
Call-ID: 1536d1554749f3957bdfebb548bcf9b7 at 10.11.220.1
CSeq: 101 BYE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Content-Length: 0


---
Destroying call '1536d1554749f3957bdfebb548bcf9b7 at 10.11.220.1'



------------------- SIP DEBUG LOG ---------------------
_______________________________________________
--Bandwidth and Colocation provided by Easynews.com --

Asterisk-Users mailing list
To UNSUBSCRIBE or update options visit:
   http://lists.digium.com/mailman/listinfo/asterisk-users

More information about the asterisk-dev mailing list