ASTERISK-11949: [patch] Problems with NOTIFY due to Asterisk sending wrong CALL-ID and duplicate sip: tag in header of NOTIFY

[Home]

Summary: ASTERISK-11949: [patch] Problems with NOTIFY due to Asterisk sending wrong CALL-ID and duplicate sip: tag in header of NOTIFY

Reporter: Volker Kettenbach (vsauer) Labels:

Date Opened: 2008-04-30 14:10:57 Date Closed: 2008-12-10 13:01:19.000-0600

Priority: Major Regression? No

Status: Closed/Complete Components: Channels/chan_sip/Subscriptions

Versions: Frequency of
Occurrence

Related
Issues:

Environment: Attachments: ( 0) cli_log.txt
( 1) full.debug.gz
( 2) full.debug.gz
( 3) habile-01.tar.gz
( 4) habile-02.tar.gz
( 5) mwi-1.4.18-tryout.patch
( 6) new-trace-debug-5-verbose-3-sip-debug.txt
( 7) patch001.diff
( 8) sip_subscription_id.pcap
( 9) sip-debug.txt
(10) trimmed_trace.TXT

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@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@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@192_168_0_15

In Packet 3 - which is the notify of changed count of messages in VM, the Call-ID is:
67ffd8e6092c427f3e23547d06841655@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@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@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

****** ADDITIONAL INFORMATION ******

Packet 1: Asterisk -> Siemens

NOTIFY sip:gigaset11@192.168.0.15:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.1:5060;branch=z9hG4bK420697af;rport
From: "asterisk" <sip:asterisk@volker-sauer.de>;tag=as14f589bf
To: <sip:sip:gigaset11@192.168.0.15:5060>;tag=4293876579
Contact: <sip:asterisk@192.168.0.1>
Call-ID: 1259484430@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@volker-sauer.de
Voice-Message: 1/0 (0/0)

Packet 2: Siemens -> Asterisk

SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.1:5060;branch=z9hG4bK420697af;rport=5060
From: "Gigaset <11>" <sip:gigaset11@volker-sauer.de>;tag=as14f589bf
To: "Gigaset <11>" <sip:gigaset11@volker-sauer.de>;tag=4293876579
Call-ID: 1259484430@192_168_0_15
CSeq: 102 NOTIFY
Contact: <sip:gigaset11@192.168.0.15:5060>
Supported: replaces
Allow: INVITE, ACK, CANCEL, BYE, OPTIONS, INFO, REFER, SUBSCRIBE, NOTIFY
Content-Length: 0

now deletion of message => VM emtpy

Packet 3: Astersik -> Siemens

NOTIFY sip:gigaset11@192.168.0.15:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.1:5060;branch=z9hG4bK3bc5203d;rport
From: "asterisk" <sip:asterisk@volker-sauer.de>;tag=as7700d016
To: <sip:gigaset11@192.168.0.15:5060>
Contact: <sip:asterisk@192.168.0.1>
Call-ID: 67ffd8e6092c427f3e23547d06841655@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@volker-sauer.de
Voice-Message: 0/0 (0/0)

Packet 4: Siemens -> Asterisk

SIP/2.0 481 Call Leg/Transaction Does Not Exist
Via: SIP/2.0/UDP 192.168.0.1:5060;branch=z9hG4bK3bc5203d;rport=5060
From: "asterisk" <sip:asterisk@volker-sauer.de>;tag=as7700d016
To: <sip:gigaset11@192.168.0.15:5060>
Call-ID: 67ffd8e6092c427f3e23547d06841655@volker-sauer.de
CSeq: 102 NOTIFY
Content-Length: 0

Comments: By: Olle Johansson (oej) 2008-05-01 07:26:56

I've noticed the same. Thanks for the report. Please note that for SIP bugs in Asterisk, the bug guidelines instructs you to upload a SIP debug from Asterisk, not a pcap. the PCAP tells us nothing about what goes on within your Asterisk, whereas a SIP debug log file with debug set to 5 and verbose set to 5 will tell us all we need in order to track this scenario down.
By: ibercom (ibercom) 2008-05-01 15:05:47

I think than it is similar to http://bugs.digium.com/view.php?id=10756.
Asterisk 1.4.18 no problem, no error. Bug fixed.
Asterisk 1.4.19, phone Thomson ST2030, a lot of error "Remote host can't match request NOTIFY to call ... Giving up". Bug reopened ?
By: Volker Kettenbach (vsauer) 2008-05-02 05:04:52

http://bugs.digium.com/view.php?id=10756
needs to be reopened. Bug (still) exists in 1.4.20-rc1:

<------------>
Reliably Transmitting (NAT) to 192.168.0.15:5060:
NOTIFY sip:gigaset11@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@volker-sauer.de>;tag=as305e2687
To: <sip:sip:gigaset11@192.168.0.15:5060>;tag=1492899307
Contact: <sip:asterisk@192.168.0.1>
Call-ID: 11287206@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@volker-sauer.de
Voice-Message: 1/0 (0/0)
By: Volker Kettenbach (vsauer) 2008-05-02 05:08:04

Tried with 1.4.20-rc1:

See attached logfile cli_log.txt

Same result.

By: Volker Kettenbach (vsauer) 2008-05-02 05:24:34

Tried with 1.4.18

- Can confirm that sip:sip: bug doesn't exist here
- Bit MWI doesn't work at all for Gigaset S685 in 1.4.18 even not after rebooting the S685
By: petergg (petergg) 2008-06-01 09:42:04

hi,
ich can confirm this problem. SIP-Phone ( Thomson ST 2030)
No problems with 1.4.18, but with all Versions > 1.4.18.

Should i upload more Logs?

By: Ramon Peek-Fares (ramonpeek) 2008-06-10 07:35:11

Hello Olle!
I can confirm we have seen this issue too when an extension is send a new MWI.
But we are running Asterisk 1.4.18!

So it can't be said it doesn't occur in 1.4.18

In fact the watchfull eye of my collegue Theo noticed a fault in the code.
I've uploaded a patch which resolves the issue I encoutered.
By: Ramon Peek-Fares (ramonpeek) 2008-06-10 07:37:45

please note: The patch is based on 1.4.20.1
By: petergg (petergg) 2008-06-10 11:22:12

hi,
thx for the patch.
but this patch doesn't resolv our problem.
By: petergg (petergg) 2008-06-10 13:24:17

Hi,
i have uploaded the complete sip-debug.
It seems, that Asterisk send two different Caller-IDs.

Call-ID: 17b2-c0a80101-5-1@192.168.0.33
Call-ID: bf6783f1-c0a80101-d-4d@192.168.0.33

---snipp---

<------------->
--- (7 headers 0 lines) ---
[Jun 10 20:25:06] WARNING[7320]: chan_sip.c:12916[0 ;37;40m handle_response: Remote host can't match request NOTIFY to call 'bf6783f1-c0a80101-d-4d@192.168.0.33'. Giving up.
---snipp---

By: Ramon Peek-Fares (ramonpeek) 2008-06-10 17:26:00

Ok we have two problems here;

- The patch should solve the "sip:sip:" issue which for some reason wasn't resolved after issue 10756??

- The other is that your phone rejects the NOTIFY message containing the new MWI information.

What I can see is that the Call-ID used in the NOTIFY message is that of the first REGISTER attempt which fails because of Proxy authentication. At the second attempt a new Call-ID is used and this Call-ID should most likely also be used in the NOTIFY message. (Snom phones probably indeed accept it due to the "support broken registrar" setting).

However I am unsure whether the Call-ID used would not be allowed anyway.
I guess Olle (oej) might know the answer, Olle??

But before he answers, he probably first want to see a full trace using; debug=5, verbose=5 and sip debug turned on
Just change your logger.conf to do this and you'll get these traces.

Let me also remind you to check whether you have qualify=yes enabled at the peer of the Gigaset/Thompson. For some reason Asterisk will remove the MWI subscriptions after sending a qualify message to the phone.
This is described and solved in http://bugs.digium.com/view.php?id=12828

I hope I've been helpful ;-)

By: petergg (petergg) 2008-06-11 03:50:35

hi,
thanks for your answers.
You are right, that the sip:sip: bug is now solved.
But die MWI problem ( Wrong CALL-ID ) is not solved.
qualify=no is set everywhere.
By: Chris Stone (habile) 2008-06-19 14:22:01

I don't know if this helps or hinders. I have this exact problem also with my Gigaset S450IP - however, it does not seem to occur for the first extension which is defined, i.e. I have 3 handsets registered on the Gigaset, 1100, 1101 and 1102 - each register with different extension numbers to Asterisk.

1100 gets and uses MWI correctly however, 1101 and 1102 exhibit the symptoms below (where the incorrect Call-ID is used and generate the 'Remote host ....'

So I'm really not sure that this is an Asterisk issue - I feel more that Siemens screwed up - but it is only a feeling.
By: petergg (petergg) 2008-07-01 03:36:29

hi,
this problem have not exist in version 1.4.18 . So I think this is not a phone issue.
By: petergg (petergg) 2008-07-01 10:21:03

hi,
i think after this changelog between (1.4.18 an 1.4.19xx), the problem exists:

Revision 103763 - (view) (download) (as text) (annotate) - [select for diffs]
Modified Mon Feb 18 15:33:14 2008 UTC (4 months, 1 week ago) by file
File length: 660952 byte(s)
Diff to previous 103385

Don't care if the extension given doesn't exist for subscription based MWI.

----
or this:

2008-02-25 16:16 +0000 [r104082-104084] Joshua Colp <jcolp@digium.com>

* channels/chan_sip.c: If a resubscription comes in for a dialog we
no longer know about tell the remote side that the dialog does
not exist so they subscribe again using a new dialog. (closes
issue ASTERISK-10305) Reported by: s0l4rb03 Patches: 10727-2.diff
uploaded by file (license 11)

By: Ramon Peek-Fares (ramonpeek) 2008-07-02 04:22:29

Hi there!

I've looked at the traces together with Olle (oej) and concluded that there really is no wrong CALL-ID.
We were thinking incorrectly when we/I said that we didn't use the same CALL-ID in the Notify as the one used at Registration.
Since the registration process is totally separated from the subscription process these two should not be mixed up.

Looking at the SIP SUBSCRIBE from the phone we can see it used CALL-ID: bf6783f1-c0a80101-d-4d@192.168.0.33
Further down we see asterisk sending a NOTIFY with the CALL-ID: bf6783f1-c0a80101-d-4d@192.168.0.33
These are the same CALL-ID's and thus correct!

Talking to Olle on the phone we though it might be caused by mixed up tag's or a wrong CSeq. To make sure what is really wrong we would need some more traces.

Could you please provide a new Asterisk trace with Debug level 5, Verbose level 3 and SIP debug on?
By: petergg (petergg) 2008-07-02 04:55:26

hi, thanks for the answers.
i uploaded a new trace. new-trace-debug-5-verbose-3-sip-debug.txt

I think i have found something:
First To-Statement:
To: <sip:sip:20@192.168.0.31:5060;user=phone>;tag=c0a80101-18e1

Second To-Statement:
To: <sip:sip@192.168.0.31:5060;user=phone>;tag=c0a80101-18e1

------
The second ist without the "20" bevor the @
By: Ramon Peek-Fares (ramonpeek) 2008-07-02 05:41:21

The "sip:sip:20@..." in contrast to the "sip:sip@" is most likely caused by the phone deleting the second "sip:20" from the URL since it is incorrect.
The "sip:sip" should not occur once you have applied the patch001.diff.
Did you apply this patch?

Secondly, make sure not to cut the traces too short.
Don't worry about adding a trace file that is 100Kb long, that really isn't a problem.
We just really need to see WARNING, DEBUG And VERBOSE messages.
Just make sure to provide a trace from the very beginning (that includes the REGISTER and SUBSCRIBE of the phone.)
The best thing to do is to;
- disconnect the phone
- start the trace
- connect the phone
- wait for the 'Call leg does not exist' error
- stop the trace.

PS:
If the trace is very large ( > 500Kb ) due to lots of other not important events, you can cut these out. But be very careful not to cut things, that you might think are of no importance but in fact are.
A good hint is to look at the number in between the () in front of errors, warnings and verbose messages, this number is unique per call leg.
By: petergg (petergg) 2008-07-02 06:05:20

hi,
the patch001.diff doesn't solve the problem.
i will setup a second asterisk-server to have better trace-logs.
By: Chris Stone (habile) 2008-07-02 06:23:43

Sorry, had a few technical brain issues this morning hence I seem to have uploaded my trace twice... sorry about that, but I thought it may help.

For your info, subscribe for 1100 works but not for 1101 and 1102.

C.

By: Ramon Peek-Fares (ramonpeek) 2008-07-02 07:20:21

You mentioned peers 1101 and 1102, but from these peers I do not see any succesfull SUBSCRIBE messages.
However peer 1100 does have a succesfull SUBSCRIBE and further on in the trace a failed NOTIFY. (And you said it worked??)

Anyway... looking at this peer I can see that that it uses a different CALL-ID in the NOTIFY then what was used in the SUBSCRIBE.
It looks like subscriptions get messed up or an older subscriptions is not deleted.
Also I can see to different domainparts; "@192.168.1.16" and "@192_168_1_100"?
You would't happen to have two devices trying to register under the same name and thus Voicemail name? (one at 192.168.1.100 and one at 192.168.1.16)
(I trimmed the trace down a bit and you can see the sequence more clearer in the attached "trimmedtrace.txt" file)

But I guess it would be even better to supply even cleaner traces than this one, just as you already suggested.
I especially would like to see those since you are mentioning problems with 1101 and 1102 of which no SUBSCRIBE is available in this trace.
Also you could create this trace from the boot of asterisk, meaning we won't miss any subscribes and also no other interfering peers or old call-legs.

I get the feeling we are getting closer.. ;-)

PS:
When you mentioned that the patch did not fix the problem...
Did you meant it didn't fix the "sip:sip" issue or the "Call leg does not exist" issue?
By: petergg (petergg) 2008-07-02 07:22:33

hi,
the patch does not fix the "Call leg does not exist" issue. But the sip:sip: issue.
By: Chris Stone (habile) 2008-07-02 07:43:54

OK - so maybe I've confused a little by throwing my trace in here (which is obviously different to petergg's). I just thought it may throw a different perspective on it.

Here's my setup to clarify. Asterisk server is 192.168.1.16
Siemens Gigaset is 192.168.1.100
On the Gigaset are registered 3 x peers, 1100, 1101 and 1102. Each with identical config on both the gigaset and in Asterisk.

I say it works for 1100 because I see:

asterisk1*CLI> sip show subscriptions
Peer User Call ID Extension Last state Type Mailbox
192.168.1.100 1100 289579435@1 -- <none> mwi 1100@defau
1 active SIP subscription
asterisk1*CLI>

but nothing for 1101 or 1102.

I must have missed that 1100 also threw a 481 error but usually when I looked, that peer was OK and it was always the other 2 that threw 481s back.

Sorry, also, for my trace, it includes the startup/shutdown of Asterisk so should be complete. I started Asterisk and powered up the Gigaset.

Let me know what I can provide that may help.

C.

By: Chris Stone (habile) 2008-07-02 07:53:55

[QUOTE]
I see the domainparts "@192.168.1.16" and "@192_168_1_100"? Are two peers interfering with each other??

So I just checked the Gigaset config and it looks like in my 'experimentation' I had set outbound proxy to 192.168.1.16 (Asterisk server) and set it to 'always' - could that account for it?
By: ibercom (ibercom) 2008-07-09 17:44:24

Hi pettergg,

Now I haven't "Remote host can't match request NOTIFY to call ... Giving up" errors with phone Thomson ST2030. It's ok.

I saw your note:

"Revision 103763 - (view) (download) (as text) (annotate) - [select for diffs]
Modified Mon Feb 18 15:33:14 2008 UTC (4 months, 1 week ago) by file
File length: 660952 byte(s)
Diff to previous 103385

Don't care if the extension given doesn't exist for subscription based MWI."

And I have applied the patch1 and change/cancel the revision 103763 in chan_sip:

--- if (strcmp(event, "message-summary") && gotdest) {
--->
+++ if (gotdest) {

I don't know but my sistem is ok, no more errors.
What's happens ?
I hope that this can help you.
By: petergg (petergg) 2008-07-10 08:16:49

hi ibercom,
thanks for your info.
--- if (strcmp(event, "message-summary") && gotdest) {
--->
+++ if (gotdest) {
->> The patch works for me too. ;-)

BTW: patch001.diff
also solve the sip:sip: problem.

By: Ramon Peek-Fares (ramonpeek) 2008-07-11 08:54:03

HA!

That explaines why I could reproduce it!
I already had revision 103763 included in my system.

I guess this solves the issue completely.
Or is someone still having troubles??
By: Chris Stone (habile) 2008-07-11 10:23:43

Thanks everyone. OK, in layman's terms, what do I actually need to do to get this fixed in 1.4.21-1?

I need to apply that diff

--- if (strcmp(event, "message-summary") && gotdest) {
--->
+++ if (gotdest) {

to chan_sip.c and apply patch001.diff right?

Sorry to be a little thick but ... it's Friday.
By: Ramon Peek-Fares (ramonpeek) 2008-07-11 10:34:51

Yes you need to apply both the patch001.diff as the patch in revision 103763
which is;
--- if (strcmp(event, "message-summary") && gotdest) {
--->
+++ if (gotdest) {

If everyone would like to test their systems with these patches applied we can check for sure whether the issue is solved.

Thanks ibercom for reminding me of the fact the petergg already reported he noticed revision 103763, I somehow overlooked it :-(
It indeed seems to be very much related...
By: Chris Stone (habile) 2008-07-11 10:52:08

hmm... I still get:

[Jul 11 16:59:23] WARNING[23079] chan_sip.c: Remote host can't match request NOTIFY to call '40c10b6412373cfd0c908f1c7de9d7fd@192.168.1.16'. Giving up.
[Jul 11 16:59:23] WARNING[23079] chan_sip.c: Remote host can't match request NOTIFY to call '201201b07ab476a17fa7786466299950@192.168.1.16'. Giving up.
[Jul 11 16:59:23] WARNING[23079] chan_sip.c: Remote host can't match request NOTIFY to call '2e06380e1e52901d3dd330620e395823@192.168.1.16'. Giving up.

It actually seems slightly worse because now I have no MWI subscriptions at all and MWI is not working for the first Siemens extension now, where it was before.

:o(

By: Ramon Peek-Fares (ramonpeek) 2008-07-11 11:01:15

Habile: perhaps you are having a different issue.
It seems many people are seeing this error but there are multiple reason for why it is occuring.

Would it be too much to ask to upload a trace (habile-01.tar) with Debug level 5, Verbose level 3 and SIP debug on?
And please make sure that Asterisk has just been rebooted for reproducing the issue, making sure we do not see any 'trash' of other issues.
By: Chris Stone (habile) 2008-07-11 11:16:08

No problem - and thanks ramonpeek. Log is uploaded.

In fact it doesn't appear any different to before, I DO see a MWI subscription for the first Gigaset extension (1100) but not the other two (1101/1102) and it is those two I think that give the 481.

By: Ramon Peek-Fares (ramonpeek) 2008-07-11 11:50:18

I now see what is going wrong in your case (habile):

"Asterisk is sending a MWI NOTIFY to ALL peers registered at the same IP address, if only one or more peers have subscribed to MWI at that IP address."

This obviuosly shouldn't happen, only the peers that have subscribed to MWI should receive the MWI NOTIFY messages.

Your phone indeed only subscribes to MWI with peer 1100 and not 1101 or 1102!
If you want MWI for all peers you somehow need to configure your phone to do so. (so that part isn't an Asterisk issue)

However Asterisk should not send MWI NOTIFY Messages to peers that haven't subscribed! I'll look into that and see what might be causing that.

By: Ramon Peek-Fares (ramonpeek) 2008-07-11 11:54:02

Habile, Short question:
Do you have the "mailbox=xxxx" setting in sip.conf for the peers 1101 & 1102?

And... Is it possible for you to check this in asterisk-1.4.21.1?
I don't have your type of phone so I can't really check this..

By: Ramon Peek-Fares (ramonpeek) 2008-07-11 13:48:56

Habile:

I've tried reproducing the issue using Snom phones with multiple subscriptions, but I cannot seem to duplicate the issue.
So I suspect it has something todo with the way in which your phone subscribes peer 1100 to MWI.
Somehow this makes Asterisk think there is also a subscription for peers 1101 & 1102.
However I did find something rather weird in the code, which might solve your the Asterisk part of the problem and thus not send a NOTIFY to a none subscribed peer.

Could you please try the mwi-1.4.18-tryout.patch I just uploaded.
It works fine at my PBX, but I cannot duplicate the issue, so perhaps you can check to see whether it solves the issue?
By: Ramon Peek-Fares (ramonpeek) 2008-07-11 13:50:24

I'll be off to celebrate the weekend...
Keep testing ;-)
By: Chris Stone (habile) 2008-07-11 14:10:27

Many thanks Ramonpeek. I do have mailbox= for all three extensions as this is desired. Unfortunately the Gigaset only has ONE IP address so I'm a bit stuffed there. Also, I use Freepbx which insists on adding a mailbox= entry regardless of whether a mailbox is in use or not.

I'll try the patch anyway (and thank you for that) and let you know. But from the sounds of it I'm screwed either way.

C.
By: Volker Kettenbach (vsauer) 2008-07-11 15:48:11

ramonpeek:
For some reason the Snom phones behave differently. Snoms have options like "accept broken registrar" which may cause this.
By: Ramon Peek-Fares (ramonpeek) 2008-07-11 18:19:22

vsauer:
In my case the setting "accept broken registrar" is of no importance.
Since Asterisk is not sending the MWI NOTIFY messages to any peer that didn't subscribe, unlike what we can see in habile's traces.

habile:
Don't worry too much... you're not "screwed" yet.
There must be a reason for the behaviuor we are seeing, let's first try to find it. ;-)
By: Chris Stone (habile) 2008-07-12 04:59:32

I tried the mwi-1.4.18-tryout.patch - still the same.

I've uploaded another trace in case it's of use. I can always arrange direct access to the box if you think it will help - but that's probably going to cost a lot of beers :)

C.
By: Ramon Peek-Fares (ramonpeek) 2008-07-14 02:15:43

Habile:
I looked at your issue again and think I've found the Asterisk part of your problem.
The patch I created should NOT be applied, however it did gave me insight into what is most likely wrong. I'm probably a bit stupid for not asking you about this before...

Do you have the setting "subscribemwi=yes" defined for all peers with mailboxes?
If not, Asterisk will not check whether the peer has subscribed to Voicemail at Asterisk and send the MWI Notify if there is any message in the mailbox.
If yes, Asterisk will only send a MWI Notify if the peer has subscribed.

So if you define the "subscribemwi=yes" at each peer that uses a mailbox you shoudn't see those warnings anymore. However you should still need to figure out how to make your Siemens S450 register to voicemail for all it's 'lines' and not only the first one.

By: Chris Stone (habile) 2008-07-14 03:21:08

You got it! Yep, I do NOT have a subscribemwi option defined at all - I need to feed this back to the FreePBX team. I manually added them and I see the message no more. Still only have one subscription though but as you say, that's another issue.

Thanks so much ramonpeek for your perseverance. I've given up with Siemens, getting them to acknowledge or even understand the issue at hand is not a challenge I'm prepared for - need to get some proper phones :)
By: Ramon Peek-Fares (ramonpeek) 2008-07-14 03:31:54

OK, great!!
It seems another piece of the puzzle is being solved.

OK let's recapture the events;
=================================

- The patch001.diff solved the "sip:sip" problem
- Revision 103763 "Don't care if the extension given doesn't exist for subscription based MWI" also solved a part of the problem.

vsauer:
Can this issue now be closed?
It seems to me that everybody has found there answer/solution?
By: Volker Kettenbach (vsauer) 2008-07-14 07:08:18

ramonpeek:

Indeed, I did not have subscribemwi=yes in my sip.conf.
Adding it solved the problem with the Siemens phone.
The bug can be closed.
Thanks for alle this effort!
By: ibercom (ibercom) 2008-07-14 08:39:14

ramonpeek in your note:

>OK let's recapture the events;
>=================================
>
YES >- The patch001.diff solved the "sip:sip" problem
NO >- Revision 103763 "Don't care if the extension given doesn't exist for >subscription based MWI" also solved a part of the problem.

The correct answer is UNDO Revision 103763.
The Revision 103763 is part of the problem.

Thanks for all.
By: petergg (petergg) 2008-07-14 09:27:03

hi,

ibercom is correct.
The Revision 103763 was the main problem.
By: Ramon Peek-Fares (ramonpeek) 2008-07-14 10:06:36

I believe revision 103763 is still correct.
I guess it might appear to solve your issues, however setting the 'subscribemwi=yes' also solves your issue..
By: petergg (petergg) 2008-08-26 03:11:16

subscribemwi=yes' does not solve the issue with ST2030.
only
--- if (strcmp(event, "message-summary") && gotdest) {
--->
+++ if (gotdest) {

solve the problem for me.
By: Chris Stone (habile) 2008-08-26 09:12:06

OK. For me it was a stupid oversight in the (mis)configuration of my Siemens S450IP. In settings, under Telephony->Network Mailbox the 2 extensions that were giving the 481 Call Leg/Transaction Does Not Exist were not marked as active. Once I'd marked them as active all subscriptions worked correctly, as does MWI for every extension - doh!

I don't know about the other devices being discussed here, maybe there is a problem affecting those still but just thought I'd update this ticket.

By: ibercom (ibercom) 2008-11-03 02:54:00.000-0600

I think so that it is a subscriptions problem.
I have a Thomson ST2030, I wrote the note (0089978) and I have been investigating something more. If I apply this:

--- if (strcmp(event, "message-summary") && gotdest) {
--->
+++ if (gotdest) {

The telephone don't subscribe to MWI and no errors, it don't find the extension (config problem), it is OK.
The problem is when the telephone try subscribe, correctly, to MWI. The first time something happens, until a pair of re-subscribed it doesn't become stable and OK:

asterisk1*CLI> sip show subscriptions
Peer User Call ID Extension Last state Type Mailbox
172.19.12.4 20087 3c8015-c0a8 -- <none> mwi 20087@aste
172.19.12.39 43140 329f7a-c0a8 -- <none> mwi 43140@aste
172.19.23.212 20170 5442-c0a801 -- <none> mwi 20170@aste
172.19.23.196 46135 5a09-c0a801 -- <none> mwi 46135@aste
172.19.22.139 20205 412d-c0a801 -- <none> mwi 20205@aste
172.19.22.139 20205 49fe-c0a801 -- <none> mwi 20205@aste
172.19.23.195 43462 61b8-c0a801 -- <none> mwi 43462@aste
172.19.12.3 20097 2a545c-c0a8 -- <none> mwi 20097@aste
172.19.11.162 20091 2a4999-c0a8 -- <none> mwi 20091@aste
172.19.11.161 44232 2a5b13-c0a8 -- <none> mwi 44232@aste
10 active SIP subscriptions

[Nov 3 08:43:03] NOTICE[30123] chan_sip.c: Peer '20205' is now UNREACHABLE! Last qualify: 16
[Nov 3 08:43:26] NOTICE[30123] chan_sip.c: Peer '20205' is now Reachable. (33ms / 2000ms)
[Nov 3 08:43:26] WARNING[30123] chan_sip.c: Remote host can't match request NOTIFY to call '49fe-c0a80101-d-2@172.19.22.139'. Giving up.
[Nov 3 08:44:30] NOTICE[30123] chan_sip.c: Peer '20205' is now UNREACHABLE! Last qualify: 33
[Nov 3 08:45:27] NOTICE[30123] chan_sip.c: Peer '20205' is now Reachable. (20ms / 2000ms)
[Nov 3 08:45:27] WARNING[30123] chan_sip.c: Remote host can't match request NOTIFY to call '412d-c0a80101-d-2@172.19.22.139'. Giving up.

asterisk1*CLI> sip show subscriptions
Peer User Call ID Extension Last state Type Mailbox
172.19.22.139 20205 1796ab-c0a8 -- <none> mwi 20205@aste
172.19.12.4 20087 3c8015-c0a8 -- <none> mwi 20087@aste
172.19.12.39 43140 329f7a-c0a8 -- <none> mwi 43140@aste
172.19.23.212 20170 5442-c0a801 -- <none> mwi 20170@aste
172.19.23.196 46135 5a09-c0a801 -- <none> mwi 46135@aste
172.19.22.139 20205 49fe-c0a801 -- <none> mwi 20205@aste
172.19.23.195 43462 61b8-c0a801 -- <none> mwi 43462@aste
172.19.12.3 20097 2a545c-c0a8 -- <none> mwi 20097@aste
172.19.11.162 20091 2a4999-c0a8 -- <none> mwi 20091@aste
172.19.11.161 44232 2a5b13-c0a8 -- <none> mwi 44232@aste
10 active SIP subscriptions

[Nov 3 09:15:47] WARNING[30123] chan_sip.c: Remote host can't match request NOTIFY to call '1796ab-c0a80101-d-4@172.19.22.139'. Giving up.

I have two subscriptions for 20205 in Asterisk, is it possible ? And the telephone try again:

asterisk1*CLI> sip show subscriptions
Peer User Call ID Extension Last state Type Mailbox
172.19.23.212 20170 2a53fe-c0a8 -- <none> mwi 20170@aste
172.19.23.196 46135 1c1b4e-c0a8 -- <none> mwi 46135@aste
172.19.11.242 20084 e55b9-c0a80 -- <none> mwi 20084@aste
172.19.22.139 20205 3390dd-c0a8 -- <none> mwi 20205@aste
172.19.21.16 20338 4e86-c0a801 -- <none> mwi 20338@aste
172.19.23.195 43462 1c24cc-c0a8 -- <none> mwi 43462@aste
172.19.12.4 20087 3c8015-c0a8 -- <none> mwi 20087@aste
172.19.12.39 43140 329f7a-c0a8 -- <none> mwi 43140@aste
172.19.12.3 20097 2a545c-c0a8 -- <none> mwi 20097@aste
172.19.11.162 20091 2a4999-c0a8 -- <none> mwi 20091@aste
172.19.11.161 44232 2a5b13-c0a8 -- <none> mwi 44232@aste
11 active SIP subscriptions

Now it is OK, I have a subscription for 20205. The log is empty, no more error "Remote host can't match request NOTIFY".

What's happens ???
By: Digium Subversion (svnbot) 2008-12-10 13:01:12.000-0600

Repository: asterisk
Revision: 162804

U branches/1.4/channels/chan_sip.c

------------------------------------------------------------------------
r162804 | file | 2008-12-10 13:01:12 -0600 (Wed, 10 Dec 2008) | 6 lines

Fix subscription based MWI up a bit. We only want to put sip: at the beginning of the URI if it is not already there and revert code to ignore destination check if subscribing for MWI.
(closes issue ASTERISK-11949)
Reported by: vsauer
Patches:
patch001.diff uploaded by ramonpeek (license 266)

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=162804