[Asterisk-Users] SIP: INFO before answer causes disconnect

Alan Ferrency alan at pair.com
Thu Mar 30 09:15:31 MST 2006 

Hi. We have an odd problem with incoming SIP calls. I have attached a
SIP debug log, with some asterisk verbosity as well, demonstrating the
problem, below.

Is this a known bug?

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


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've finally 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.

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 ---------------------

More information about the asterisk-users mailing list