[asterisk-bugs] [Asterisk 0012560]: Problems with NOTIFY due to Asterisk sending wrong CALL-ID and duplicate sip: tag in header of NOTIFY
noreply at bugs.digium.com
noreply at bugs.digium.com
Fri May 2 05:08:04 CDT 2008
A NOTE has been added to this issue.
======================================================================
http://bugs.digium.com/view.php?id=12560
======================================================================
Reported By: vsauer
Assigned To: oej
======================================================================
Project: Asterisk
Issue ID: 12560
Category: Channels/chan_sip/Subscriptions
Reproducibility: always
Severity: major
Priority: normal
Status: assigned
Asterisk Version: 1.4.19
SVN Branch (only for SVN checkouts, not tarball releases): N/A
SVN Revision (number only!):
Disclaimer on File?: N/A
Request Review:
======================================================================
Date Submitted: 04-30-2008 14:10 CDT
Last Modified: 05-02-2008 05:08 CDT
======================================================================
Summary: Problems with NOTIFY due to Asterisk sending wrong
CALL-ID and duplicate sip: tag in header of NOTIFY
Description:
Hi,
(first of all: I'm not an expert on SIP. So I might be completly wrong.
Don't take it personally).
I have the following problem with 1.4.19:
Leaving ore deleting a message on/from the voicemail does not correctly
trigger the MWI LED on a Siemens Gigaset S685 while it does on a Snom 370.
A lot of people may claim this is a bug of the 685, but I think it isn't.
It's related to Asterisk.
For some reason the Snom behaves more tolerant (Snoms have options like
"accept broken registrar" etc), but the 685 doesn't.
Here's the exakt problem:
Step 1) Restart Asterisk, Shut down Siemens S685
Step 2) Leave a message on voicemail
VM is registerd in all phones and setup in voicemail.conf
Snom phone (which is on all the time) starts blinking
Step 3) Power on Siemens S685
Siemens get subscription:
arthur*CLI> sip show subscriptions
Peer User Call ID Extension Last state
Type Mailbox
192.168.0.15 gigaset11 1259484430@ -- <none>
mwi 101 at defaul
MWI LED starts blinking.
Step 4) Take another phone (like the Snom), goto mailbox and delete
message
-> Snom stops blinking
-> S685 doesn't, MWI still blinking
After deletion of the messgae, CLI shows:
[Apr 30 20:33:27] WARNING[16137]: chan_sip.c:12814 handle_response: Remote
host can't match request NOTIFY to call
'67ffd8e6092c427f3e23547d06841655 at volker-sauer.de'. Giving up.
See dump of packages in additional information.
You can see, that in Packet 1, the Call-ID of the subscriprion is
1259484430 at 192_168_0_15
In Packet 3 - which is the notify of changed count of messages in VM, the
Call-ID is:
67ffd8e6092c427f3e23547d06841655 at volker-sauer.de
which is therefore rejected by the Siemens in Packet 4:
481 Call Leg/Transaction Does Not Exist
Somehow Snom phons accept this, though.
What is weired, too:
Look at the To field in packet 1:
To: <sip:sip:gigaset11 at 192.168.0.15:5060>;tag=4293876579
why "sip:sip:...." is this correct? Lookes like a typo..
and somehow it's correct in package 3:
To: <sip:gigaset11 at 192.168.0.15:5060>
I'll add a wireshark dump of the 4 packages in case additional information
is needed.
To my understanding, the Siemens seems to be right by rejecting the
NOTIFY. And this could be a bug of Asterisk.
Maybe it's related too:
http://bugs.digium.com/view.php?id=6848
See the message of caspy on 04-03-06 06:25
"It seems, that this is because NOTIFY request come with 'tag' field in
"From:" header different to one, that was given by phone in SUBSCRIBE
request."
Maybe this could be related, too.
Regards
Volker
======================================================================
----------------------------------------------------------------------
vsauer - 05-02-08 05:08
----------------------------------------------------------------------
Tried with 1.4.20-rc1:
Asterisk 1.4.20-rc1 has on waiting message.
Now I switch on the gigaset11:
=========================== Full sip debug ========================
<--- SIP read from 192.168.0.15:5060 --->
REGISTER sip:volker-sauer.de SIP/2.0
Via: SIP/2.0/UDP
192.168.0.15:5060;branch=z9hG4bKa50551294746c724e6a08d1382c0b143;rport
From: "Gigaset <11>" <sip:gigaset11 at volker-sauer.de>;tag=2872171903
To: "Gigaset <11>" <sip:gigaset11 at volker-sauer.de>
Call-ID: 1968291532 at 192_168_0_15
CSeq: 1 REGISTER
Contact: <sip:gigaset11 at 192.168.0.15:5060>
Max-Forwards: 70
User-Agent: S685IP020970000000
Expires: 300
Allow: INVITE, ACK, CANCEL, BYE, OPTIONS, INFO, REFER, SUBSCRIBE, NOTIFY
Content-Length: 0
<------------->
--- (12 headers 0 lines) ---
Using latest REGISTER request as basis request
Sending to 192.168.0.15 : 5060 (NAT)
<--- Transmitting (NAT) to 192.168.0.15:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP
192.168.0.15:5060;branch=z9hG4bKa50551294746c724e6a08d1382c0b143;received=192.168.0.15;rport=5060
From: "Gigaset <11>" <sip:gigaset11 at volker-sauer.de>;tag=2872171903
To: "Gigaset <11>" <sip:gigaset11 at volker-sauer.de>
Call-ID: 1968291532 at 192_168_0_15
CSeq: 1 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:gigaset11 at 192.168.0.1>
Content-Length: 0
<------------>
<--- Transmitting (NAT) to 192.168.0.15:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP
192.168.0.15:5060;branch=z9hG4bKa50551294746c724e6a08d1382c0b143;received=192.168.0.15;rport=5060
From: "Gigaset <11>" <sip:gigaset11 at volker-sauer.de>;tag=2872171903
To: "Gigaset <11>" <sip:gigaset11 at volker-sauer.de>;tag=as3694c6ce
Call-ID: 1968291532 at 192_168_0_15
CSeq: 1 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Expires: 300
Contact: <sip:gigaset11 at 192.168.0.15:5060>;expires=300
Date: Fri, 02 May 2008 09:57:41 GMT
Content-Length: 0
<------------>
Scheduling destruction of SIP dialog '1968291532 at 192_168_0_15' in 32000 ms
(Method: REGISTER)
<--- SIP read from 192.168.0.15:5060 --->
REGISTER sip:volker-sauer.de SIP/2.0
Via: SIP/2.0/UDP
192.168.0.15:5060;branch=z9hG4bK8566e9251c4af70a859b4abb926c653;rport
From: "Gigaset 13" <sip:gigaset13 at volker-sauer.de>;tag=3931030465
To: "Gigaset 13" <sip:gigaset13 at volker-sauer.de>
Call-ID: 1517407333 at 192_168_0_15
CSeq: 1 REGISTER
Contact: <sip:gigaset13 at 192.168.0.15:5060>
Max-Forwards: 70
User-Agent: S685IP020970000000
Expires: 300
Allow: INVITE, ACK, CANCEL, BYE, OPTIONS, INFO, REFER, SUBSCRIBE, NOTIFY
Content-Length: 0
<------------->
--- (12 headers 0 lines) ---
Using latest REGISTER request as basis request
Sending to 192.168.0.15 : 5060 (NAT)
<--- Transmitting (NAT) to 192.168.0.15:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP
192.168.0.15:5060;branch=z9hG4bK8566e9251c4af70a859b4abb926c653;received=192.168.0.15;rport=5060
From: "Gigaset 13" <sip:gigaset13 at volker-sauer.de>;tag=3931030465
To: "Gigaset 13" <sip:gigaset13 at volker-sauer.de>
Call-ID: 1517407333 at 192_168_0_15
CSeq: 1 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:gigaset13 at 192.168.0.1>
Content-Length: 0
<------------>
<--- Transmitting (NAT) to 192.168.0.15:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP
192.168.0.15:5060;branch=z9hG4bK8566e9251c4af70a859b4abb926c653;received=192.168.0.15;rport=5060
From: "Gigaset 13" <sip:gigaset13 at volker-sauer.de>;tag=3931030465
To: "Gigaset 13" <sip:gigaset13 at volker-sauer.de>;tag=as6b5af9a8
Call-ID: 1517407333 at 192_168_0_15
CSeq: 1 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Expires: 300
Contact: <sip:gigaset13 at 192.168.0.15:5060>;expires=300
Date: Fri, 02 May 2008 09:57:41 GMT
Content-Length: 0
<------------>
Scheduling destruction of SIP dialog '1517407333 at 192_168_0_15' in 32000 ms
(Method: REGISTER)
<--- SIP read from 192.168.0.15:5060 --->
REGISTER sip:volker-sauer.de SIP/2.0
Via: SIP/2.0/UDP
192.168.0.15:5060;branch=z9hG4bKa70e1aedd9c7839fd9adb27f80401606;rport
From: "Gigaset 14" <sip:gigaset14 at volker-sauer.de>;tag=2746316696
To: "Gigaset 14" <sip:gigaset14 at volker-sauer.de>
Call-ID: 547539130 at 192_168_0_15
CSeq: 1 REGISTER
Contact: <sip:gigaset14 at 192.168.0.15:5060>
Max-Forwards: 70
User-Agent: S685IP020970000000
Expires: 300
Allow: INVITE, ACK, CANCEL, BYE, OPTIONS, INFO, REFER, SUBSCRIBE, NOTIFY
Content-Length: 0
<------------->
--- (12 headers 0 lines) ---
Using latest REGISTER request as basis request
Sending to 192.168.0.15 : 5060 (NAT)
<--- Transmitting (NAT) to 192.168.0.15:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP
192.168.0.15:5060;branch=z9hG4bKa70e1aedd9c7839fd9adb27f80401606;received=192.168.0.15;rport=5060
From: "Gigaset 14" <sip:gigaset14 at volker-sauer.de>;tag=2746316696
To: "Gigaset 14" <sip:gigaset14 at volker-sauer.de>
Call-ID: 547539130 at 192_168_0_15
CSeq: 1 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:gigaset14 at 192.168.0.1>
Content-Length: 0
<------------>
<--- Transmitting (NAT) to 192.168.0.15:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP
192.168.0.15:5060;branch=z9hG4bKa70e1aedd9c7839fd9adb27f80401606;received=192.168.0.15;rport=5060
From: "Gigaset 14" <sip:gigaset14 at volker-sauer.de>;tag=2746316696
To: "Gigaset 14" <sip:gigaset14 at volker-sauer.de>;tag=as20764892
Call-ID: 547539130 at 192_168_0_15
CSeq: 1 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Expires: 300
Contact: <sip:gigaset14 at 192.168.0.15:5060>;expires=300
Date: Fri, 02 May 2008 09:57:41 GMT
Content-Length: 0
<------------>
Scheduling destruction of SIP dialog '547539130 at 192_168_0_15' in 32000 ms
(Method: REGISTER)
<--- SIP read from 192.168.0.15:5060 --->
SUBSCRIBE sip:gigaset11 at volker-sauer.de SIP/2.0
Via: SIP/2.0/UDP
192.168.0.15:5060;branch=z9hG4bK33b3bfcdd30e50cce2c4c3ae13466453;rport
From: "Gigaset <11>" <sip:gigaset11 at volker-sauer.de>;tag=1492899307
To: "Gigaset <11>" <sip:gigaset11 at volker-sauer.de>
Call-ID: 11287206 at 192_168_0_15
CSeq: 1419631438 SUBSCRIBE
Contact: <sip:gigaset11 at 192.168.0.15:5060>
Max-Forwards: 70
User-Agent: S685IP020970000000
Event: message-summary
Expires: 3600
Allow: NOTIFY
Accept: application/simple-message-summary
Content-Length: 0
<------------->
--- (14 headers 0 lines) ---
Creating new subscription
Sending to 192.168.0.15 : 5060 (NAT)
Found peer 'gigaset11'
Looking for gigaset11 in doLocalCalls (domain volker-sauer.de)
Scheduling destruction of SIP dialog '11287206 at 192_168_0_15' in 610000 ms
(Method: SUBSCRIBE)
<--- Transmitting (NAT) to 192.168.0.15:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP
192.168.0.15:5060;branch=z9hG4bK33b3bfcdd30e50cce2c4c3ae13466453;received=192.168.0.15;rport=5060
From: "Gigaset <11>" <sip:gigaset11 at volker-sauer.de>;tag=1492899307
To: "Gigaset <11>" <sip:gigaset11 at volker-sauer.de>;tag=as305e2687
Call-ID: 11287206 at 192_168_0_15
CSeq: 1419631438 SUBSCRIBE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Expires: 600
Contact: <sip:gigaset11 at 192.168.0.1>;expires=600
Content-Length: 0
<------------>
Reliably Transmitting (NAT) to 192.168.0.15:5060:
NOTIFY sip:gigaset11 at 192.168.0.15:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.1:5060;branch=z9hG4bK4be5c79c;rport
From: "asterisk" <sip:asterisk at volker-sauer.de>;tag=as305e2687
To: <sip:sip:gigaset11 at 192.168.0.15:5060>;tag=1492899307
Contact: <sip:asterisk at 192.168.0.1>
Call-ID: 11287206 at 192_168_0_15
CSeq: 102 NOTIFY
User-Agent: Asterisk PBX
Max-Forwards: 70
Event: message-summary
Content-Type: application/simple-message-summary
Subscription-State: active
Content-Length: 95
Messages-Waiting: yes
Message-Account: sip:Mailbox at volker-sauer.de
Voice-Message: 1/0 (0/0)
---
<--- SIP read from 192.168.0.15:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.1:5060;branch=z9hG4bK4be5c79c;rport=5060
From: "Gigaset <11>" <sip:gigaset11 at volker-sauer.de>;tag=as305e2687
To: "Gigaset <11>" <sip:gigaset11 at volker-sauer.de>;tag=1492899307
Call-ID: 11287206 at 192_168_0_15
CSeq: 102 NOTIFY
Contact: <sip:gigaset11 at 192.168.0.15:5060>
Supported: replaces
Allow: INVITE, ACK, CANCEL, BYE, OPTIONS, INFO, REFER, SUBSCRIBE, NOTIFY
Content-Length: 0
====================== sip debug end ==================================
*CLI> sip show subscriptions
Peer User Call ID Extension Last state
Type Mailbox
192.168.0.15 gigaset11 11287206 at 19 -- <none>
mwi 101 at defaul
The ID is: 11287206 at 192_168_0_15
Now Remove Voicemail Message on different phone
==================== sip full debug ====================================
Reliably Transmitting (NAT) to 192.168.0.15:5060:
NOTIFY sip:gigaset11 at 192.168.0.15:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.1:5060;branch=z9hG4bK13357c41;rport
From: "asterisk" <sip:asterisk at volker-sauer.de>;tag=as5301f135
To: <sip:gigaset11 at 192.168.0.15:5060>
Contact: <sip:asterisk at 192.168.0.1>
Call-ID: 7c3aea3006a9c1fc1f90dd5f40e4fe07 at volker-sauer.de
CSeq: 102 NOTIFY
User-Agent: Asterisk PBX
Max-Forwards: 70
Event: message-summary
Content-Type: application/simple-message-summary
Content-Length: 94
Messages-Waiting: no
Message-Account: sip:Mailbox at volker-sauer.de
Voice-Message: 0/0 (0/0)
---
Reliably Transmitting (NAT) to 192.168.0.15:5060:
OPTIONS sip:gigaset14 at 192.168.0.15:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.1:5060;branch=z9hG4bK608130db;rport
From: "asterisk" <sip:asterisk at volker-sauer.de>;tag=as4e56c300
To: <sip:gigaset14 at 192.168.0.15:5060>
Contact: <sip:asterisk at 192.168.0.1>
Call-ID: 0648500e3ebd3526557c116a0ba32d57 at volker-sauer.de
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX
Max-Forwards: 70
Date: Fri, 02 May 2008 10:01:00 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Length: 0
---
<--- SIP read from 192.168.0.15:5060 --->
SIP/2.0 481 Call Leg/Transaction Does Not Exist
Via: SIP/2.0/UDP 192.168.0.1:5060;branch=z9hG4bK13357c41;rport=5060
From: "asterisk" <sip:asterisk at volker-sauer.de>;tag=as5301f135
To: <sip:gigaset11 at 192.168.0.15:5060>
Call-ID: 7c3aea3006a9c1fc1f90dd5f40e4fe07 at volker-sauer.de
CSeq: 102 NOTIFY
Content-Length: 0
<------------->
--- (7 headers 0 lines) ---
[May 2 12:01:00] WARNING[4508]: chan_sip.c:12878 handle_response: Remote
host can't match request NOTIFY to call
'7c3aea3006a9c1fc1f90dd5f40e4fe07 at volker-sauer.de'. Giving up.
<--- SIP read from 192.168.0.15:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.1:5060;branch=z9hG4bK608130db;rport=5060
From: "asterisk" <sip:asterisk at volker-sauer.de>;tag=as4e56c300
To: <sip:gigaset14 at 192.168.0.15:5060>;tag=3562189841
Call-ID: 0648500e3ebd3526557c116a0ba32d57 at volker-sauer.de
CSeq: 102 OPTIONS
Contact: <sip:gigaset14 at 192.168.0.15:5060>
Supported: replaces
Allow-Events: refer
Allow: INVITE, ACK, CANCEL, BYE, OPTIONS, INFO, REFER, SUBSCRIBE, NOTIFY
Accept:
application/sdp,application/dtmf-relay,application/simple-message-summary,message/sipfrag
Accept-Encoding: identity
Accept-Language: en
Content-Length: 0
<------------->
--- (14 headers 0 lines) ---
Really destroying SIP dialog
'0648500e3ebd3526557c116a0ba32d57 at volker-sauer.de' Method: OPTIONS
Reliably Transmitting (NAT) to 192.168.0.15:5060:
OPTIONS sip:gigaset13 at 192.168.0.15:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.1:5060;branch=z9hG4bK3148501c;rport
From: "asterisk" <sip:asterisk at volker-sauer.de>;tag=as54b49e1f
To: <sip:gigaset13 at 192.168.0.15:5060>
Contact: <sip:asterisk at 192.168.0.1>
Call-ID: 772fd277674b8a4c79a9e5b54876e82f at volker-sauer.de
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX
Max-Forwards: 70
Date: Fri, 02 May 2008 10:01:00 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Length: 0
---
<--- SIP read from 192.168.0.15:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.1:5060;branch=z9hG4bK3148501c;rport=5060
From: "asterisk" <sip:asterisk at volker-sauer.de>;tag=as54b49e1f
To: <sip:gigaset13 at 192.168.0.15:5060>;tag=3175715637
Call-ID: 772fd277674b8a4c79a9e5b54876e82f at volker-sauer.de
CSeq: 102 OPTIONS
Contact: <sip:gigaset13 at 192.168.0.15:5060>
Supported: replaces
Allow-Events: refer
Allow: INVITE, ACK, CANCEL, BYE, OPTIONS, INFO, REFER, SUBSCRIBE, NOTIFY
Accept:
application/sdp,application/dtmf-relay,application/simple-message-summary,message/sipfrag
Accept-Encoding: identity
Accept-Language: en
Content-Length: 0
<------------->
--- (14 headers 0 lines) ---
Really destroying SIP dialog
'772fd277674b8a4c79a9e5b54876e82f at volker-sauer.de' Method: OPTIONS
Reliably Transmitting (NAT) to 192.168.0.15:5060:
OPTIONS sip:gigaset11 at 192.168.0.15:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.1:5060;branch=z9hG4bK1d80bdde;rport
From: "asterisk" <sip:asterisk at volker-sauer.de>;tag=as30bdd299
To: <sip:gigaset11 at 192.168.0.15:5060>
Contact: <sip:asterisk at 192.168.0.1>
Call-ID: 20c97d0e0a60c9835133eaff04f6e3c7 at volker-sauer.de
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX
Max-Forwards: 70
Date: Fri, 02 May 2008 10:01:00 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Length: 0
---
---
<--- SIP read from 192.168.0.15:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.1:5060;branch=z9hG4bK1d80bdde;rport=5060
From: "asterisk" <sip:asterisk at volker-sauer.de>;tag=as30bdd299
To: <sip:gigaset11 at 192.168.0.15:5060>;tag=3905971821
Call-ID: 20c97d0e0a60c9835133eaff04f6e3c7 at volker-sauer.de
CSeq: 102 OPTIONS
Contact: <sip:gigaset11 at 192.168.0.15:5060>
Supported: replaces
Allow-Events: refer
Allow: INVITE, ACK, CANCEL, BYE, OPTIONS, INFO, REFER, SUBSCRIBE, NOTIFY
Accept:
application/sdp,application/dtmf-relay,application/simple-message-summary,message/sipfrag
Accept-Encoding: identity
Accept-Language: en
Content-Length: 0
===================================== sip debug end
==================================================
7c3aea3006a9c1fc1f90dd5f40e4fe07 at volker-sauer.de is unknown to gigaset11
Issue History
Date Modified Username Field Change
======================================================================
05-02-08 05:08 vsauer Note Added: 0086304
======================================================================
More information about the asterisk-bugs
mailing list