thr3ads.net - asterisk users - [Asterisk-Users] SIP: INFO before answer causes disconnect [Mar 2006]

If this information is useful, please help other people find it:
Share via:
Alan Ferrency
2006-Mar-30 09:15 UTC
[Asterisk-Users] SIP: INFO before answer causes disconnect

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@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@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@alan.phone SIP/2.0
Via: SIP/2.0/UDP 10.11.220.1:5060;branch=z9hG4bK14f2d730;rport
From: "XXXXXXXXXX" <sip:XXXXXXXXXX@10.11.220.1>;tag=as44f0e411
To: <sip:sip_alan@alan.phone>
Contact: <sip:XXXXXXXXXX@10.11.220.1>
Call-ID: 1536d1554749f3957bdfebb548bcf9b7@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@alan.phone>
From: "XXXXXXXXXX" <sip:XXXXXXXXXX@10.11.220.1>;tag=as44f0e411
Call-ID: 1536d1554749f3957bdfebb548bcf9b7@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@alan.phone>;tag=18a7e97964d74b16i0
From: "XXXXXXXXXX" <sip:XXXXXXXXXX@10.11.220.1>;tag=as44f0e411
Call-ID: 1536d1554749f3957bdfebb548bcf9b7@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@alan.phone SIP/2.0
Via: SIP/2.0/UDP 10.11.220.1:5060;branch=z9hG4bK122884cb;rport
From: "XXXXXXXXXX" <sip:XXXXXXXXXX@10.11.220.1>;tag=as44f0e411
To: <sip:sip_alan@alan.phone>;tag=18a7e97964d74b16i0
Contact: <sip:XXXXXXXXXX@10.11.220.1>
Call-ID: 1536d1554749f3957bdfebb548bcf9b7@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@alan.phone>;tag=18a7e97964d74b16i0
From: "XXXXXXXXXX" <sip:XXXXXXXXXX@10.11.220.1>;tag=as44f0e411
Call-ID: 1536d1554749f3957bdfebb548bcf9b7@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@alan.phone>;tag=18a7e97964d74b16i0
From: "XXXXXXXXXX" <sip:XXXXXXXXXX@10.11.220.1>;tag=as44f0e411
Call-ID: 1536d1554749f3957bdfebb548bcf9b7@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@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@10.11.220.128:5060>
set_destination: Parsing <sip:sip_alan@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@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@10.11.220.1>;tag=as44f0e411
To: <sip:sip_alan@alan.phone>;tag=18a7e97964d74b16i0
Contact: <sip:XXXXXXXXXX@10.11.220.1>
Call-ID: 1536d1554749f3957bdfebb548bcf9b7@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@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@alan.phone SIP/2.0
Via: SIP/2.0/UDP 10.11.220.1:5060;branch=z9hG4bK69c4c2a2;rport
From: "XXXXXXXXXX" <sip:XXXXXXXXXX@10.11.220.1>;tag=as44f0e411
To: <sip:sip_alan@alan.phone>
Contact: <sip:XXXXXXXXXX@10.11.220.1>
Call-ID: 1536d1554749f3957bdfebb548bcf9b7@10.11.220.1
CSeq: 103 CANCEL
User-Agent: Asterisk PBX
Max-Forwards: 70
Content-Length: 0


---
Scheduling destruction of call
'1536d1554749f3957bdfebb548bcf9b7@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@alan.phone>;tag=18a7e97964d74b16i0
From: "XXXXXXXXXX" <sip:XXXXXXXXXX@10.11.220.1>;tag=as44f0e411
Call-ID: 1536d1554749f3957bdfebb548bcf9b7@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@10.11.220.1'
[Kmarvin*CLI>     -- Playing
'/var/spool/asterisk/voicemail/default/828/unavail' (language
'en')
[Kmarvin*CLI>     -- Playing 'vm-intro' (language 'en')

<-- SIP read from 10.11.220.128:5060:
BYE sip:XXXXXXXXXX@10.11.220.1 SIP/2.0
Via: SIP/2.0/UDP 10.11.220.128:5060;branch=z9hG4bK-5f8f65f4
From: <sip:sip_alan@alan.phone>;tag=18a7e97964d74b16i0
To: "XXXXXXXXXX" <sip:XXXXXXXXXX@10.11.220.1>;tag=as44f0e411
Call-ID: 1536d1554749f3957bdfebb548bcf9b7@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@alan.phone>;tag=18a7e97964d74b16i0
To: "XXXXXXXXXX" <sip:XXXXXXXXXX@10.11.220.1>;tag=as44f0e411
Call-ID: 1536d1554749f3957bdfebb548bcf9b7@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@10.11.220.1'



------------------- SIP DEBUG LOG ---------------------
Reasonably Related Threads

Search for more apparently analagous threads
asterisk users - Mar 2006 - SIP: INFO before answer causes disconnect

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

Reasonably Related Threads

Wisdom of the Ancients
