|Summary:||ASTERISK-07247: NOTIFY sent to the wrong IP address/port|
|Date Opened:||2006-06-29 00:33:00||Date Closed:||2006-10-03 16:20:06|
|Environment:||Attachments:||( 0) Debugging_BLF.txt|
|Description:||I have a single asterisk (184.108.40.206) box that has 2 separate companies hosted on it. As both companies can have the same extension numbers (i.e. 1003) things are very explicit in the dial plan. Some phones must register for extensions in both companies and also subscribe for BLF. I am using Grandstream GXP-2000 phones for these people and sometimes asterisk will send the hint info to the wrong port. Once it happens, only way to fix is restart asterisk and reboot phones to cause them to re-register. Will work for a while (1 hour to a day or 2) then the problem will appear again.|
For example, account 1 on the phone registers for company ABC, ext. 1004 and uses port 5060. Account 4 on the phone registers for company XYZC, ext. 1004 and uses port 5066. If BLF light 1 is subscribed to company ABC ext. 1003 and BLF light 2 is subscribed to company XYZC ext. 1003, a call comes in to ABC ext 1003 but asterisk send the hint info to port 5066 and not port 5060. See SIP info in additional information.
****** ADDITIONAL INFORMATION ******
Here is the peers and hints, all looks correct.
pbx*CLI> sip show peers
Name/username Host Dyn Nat ACL Port Status
xyzc-1005/xyzc-1005 10.0.30.175 D N A 5066 Unmonitored
xyzc-1004/xyzc-1004 10.0.30.183 D N A 5066 Unmonitored
xyzc-1003/xyzc-1003 10.0.30.176 D N A 5066 Unmonitored
xyzc-1001/xyzc-1001 (Unspecified) D N A 0 UNKNOWN
abc-1006/abc-1006 (Unspecified) D N A 0 Unmonitored
abc-1005/abc-1005 10.0.30.175 D N A 5060 Unmonitored
abc-1004/abc-1004 10.0.30.183 D N A 5060 Unmonitored
abc-1003/abc-1003 10.0.30.176 D N A 5060 Unmonitored
8 sip peers [7 online , 1 offline]
pbx*CLI> sip show subscriptions
Peer User Call ID Extension Last state Type
10.0.30.183 abc-1004 a599957fa94 abchint1003 Idle dialog-info+xml
10.0.30.183 xyzc-1004 8c93004b682 xyzchint1003 Idle dialog-info+xml
10.0.30.175 xyzc-1005 fa4b6209e62 xyzchint1004 Idle dialog-info+xml
10.0.30.175 xyzc-1005 29cbcd55439 xyzchint1003 Idle dialog-info+xml
10.0.30.176 xyzc-1003 894be009052 xyzchint1005 Idle dialog-info+xml
10.0.30.176 xyzc-1003 84c809555e8 xyzchint1004 Idle dialog-info+xml
10.0.30.175 abc-1005 ba2a4d7ddd4 abchint1004 Idle dialog-info+xml
10.0.30.175 abc-1005 7499347fa8e abchint1003 Idle dialog-info+xml
10.0.30.176 abc-1003 9d2ac08db1b abchint1005 Idle dialog-info+xml
10.0.30.176 abc-1003 f799087f4c4 abchint1004 Idle dialog-info+xml
10 active SIP subscriptions
Now a call comes in on Zap/1-1 and goes to abc-1003. It should send hints to 10.0.30.175:5060 and 10.0.30.183:5060
The hint info to 10.0.30.175:5060 looks fine:
Reliably Transmitting (NAT) to 10.0.30.175:5060:
NOTIFY sip:email@example.com:5060 SIP/2.0 Via: SIP/2.0/UDP 10.0.30.10:5060;branch=z9hG4bK088b2c3f;rport From: <sip:firstname.lastname@example.org;user=phone>;tag=as7b9be2c4 To: "Accounting" <sip:email@example.com>;tag=e9555c278516709f Contact: <sip:firstname.lastname@example.org> Call-ID: email@example.com CSeq: 408 NOTIFY User-Agent: Asterisk PBX Max-Forwards: 70 Event: dialog Content-Type: application/dialog-info+xml Subscription-State: active Content-Length: 236
<dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="306" state="full" entity="sip:firstname.lastname@example.org">
<dialog id="abchint1003" direction="recipient">
But the hint to 10.0.30.183 goes to port 5066 (xyzc-1004), not 5060 (abc-1004) like it should:
Reliably Transmitting (NAT) to 10.0.30.183:5066:
NOTIFY sip:email@example.com:5066 SIP/2.0 Via: SIP/2.0/UDP 10.0.30.10:5060;branch=z9hG4bK4cea4143;rport From: <sip:firstname.lastname@example.org;user=phone>;tag=as71d9fcc2 To: "Frank Thomson" <sip:email@example.com>;tag=22ec48bfb1afac9f Contact: <sip:firstname.lastname@example.org> Call-ID: email@example.com CSeq: 123 NOTIFY User-Agent: Asterisk PBX Max-Forwards: 70 Event: dialog Content-Type: application/dialog-info+xml Subscription-State: active Content-Length: 235
<dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="21" state="full" entity="sip:firstname.lastname@example.org">
<dialog id="abchint1003" direction="recipient">
|Comments:||By: Olle Johansson (oej) 2006-06-29 02:25:36|
Test using the subscribecontext configuration setting to separate the companies. Read the sip.conf.sample file in the distribution!
By: Olle Johansson (oej) 2006-06-29 02:28:09
A terminology note, since you confused me: Subscriptions and hints is not the same. hints is a dialplan item shown with "show hints" in the CLI. Subscriptions subscribe to an extension status and sends notifications. Thanks.
By: fjt99 (fjt99) 2006-06-29 11:11:39
Already using subscribecontext in sip.conf. Each has a separate context to subscribe to. Here is an example sip.conf entry:
callerid="Frank Thomson" <1004>
in the extensions file I have:
exten => abchint1003,hint,SIP/abc-1003
exten => abchint1004,hint,SIP/abc-1004
exten => abchint1005,hint,SIP/abc-1005
Similar thing is done for xyzc.
Sorry about confusion on hint/subscription comments. I used hint incorrectly, was tired as I wrote it up. Have been trying to figure out what was going on since everything else is working so well: extensions, voicemail, IVR, etc. are all separate, working properly, never had any issue (been in production for 8 months). Only BLF seems to have an issue and only on those phones with multiple registrations to the same server.
By: Olle Johansson (oej) 2006-06-30 03:01:53
I need to see a debug of the actual subscriptions coming in *and* the notifications going out. Thanks.
By: fjt99 (fjt99) 2006-06-30 17:56:00
Uploaded text file is a register/subscription (rebooted the GXP-2000) from sip debug and a notify that goes to the wrong port. This is from the live system so some names are different but config files are identical. A little extra info that may help:
10.0.30.10: Asterisk server
10.0.30.183: My phone I've been testing with. Registers as oct-1004 on port 5060 and spin-1004 on port 5066. Subscribes to oct-1003,oct-1005,spin-1003,spin-1005
10.0.30.176: A phone that registers as oct-1003 (5060) and spin-1003 (5066). Also a GXP-2000 and subscribes to oct-1004, oct-1005, spin-1004, spin-1005
Top of file to the "sip show subscriptions" is everything from the time I reset the GXP-2000 to the point it seemed to be finished.
Time passed and all worked well. Then I noticed a call come into oct-1003 and the BLF on my phone did not light (did work earlier). That trace is at the end of the file.
By: fjt99 (fjt99) 2006-07-08 19:24:44
Any more on this? My users are bugging me about getting it working. I have tried to look at the code myself but I am not well enough versed in the internals of asterisk.
By: none (algorithmn) 2006-08-07 14:52:13
i honestly think its a grandstream issue. note the differences on the port numbers for each seperate account on your grandstream hardphone. this may be your problem. i've noticed grandstream phones 'blend' different settings between accounts....
a quick solution... use 1 account per hardware phone...
hope this helps..
By: fjt99 (fjt99) 2006-08-08 18:20:19
Originally thought it was a Grandstream issue but looking at the SIP messages I can see that at times Asterisk is sending to a port other than the one used in the subscribe request for a particular subscription.
Since we have a few phones that must be subscribed to two different accounts, not realistic to use one account per hardphone. So we are simply hoping that either the asterisk developers get a chance to look into it or I am able to understand the code (ok, slim chance on the second but I do try to look at it) and fix it.
By: Serge Vecher (serge-v) 2006-08-09 08:56:53
fjt99: the sip log you've atttached does not contain any of the [debug] messages. Please follow these instructions to produce a SIP Debug log oej is looking for.
1) Prepare test environment (reduce the ammount of unrelated traffic on the server);
2) Make sure your logger.conf has the following line:
console => notice,warning,error,debug
3) restart Asterik.
4) Enable SIP transaction logging with the following CLI commands:
set debug 4
set verbose 4
5) Save complete console log to file and _attach_ said file to the bug.
By: Serge Vecher (serge-v) 2006-08-09 08:58:55
also, please make sure you update to 1.2.10 too.
By: fjt99 (fjt99) 2006-08-12 13:58:33
Have updated to 1.2.10. Will watch and see what happens.
Sorry about not getting the debug log correct, will create new one but that may take a week or two. We are moving and getting the time to experiment on the system is a little difficult.
By: fjt99 (fjt99) 2006-08-16 14:10:22
Just a quick FYI, have seen same issue in 1.2.10. Will try to make debug log ASAP but due to our move it may still be a week or two...
By: Serge Vecher (serge-v) 2006-09-06 11:11:39
ok, it's been three weeks now.
By: fjt99 (fjt99) 2006-09-11 16:50:43
Sorry for delay, but moves never go as planned...
Tried to make the debug file this weekend and the error did not appear. Finally had to stop it due to the file getting so large (ran it from Saturday morning through about noon today). Will try again in a few days and hope error shows up while the debug is going.
By: Serge Vecher (serge-v) 2006-09-13 10:07:28
alright, do test with 220.127.116.11 release too.
By: Serge Vecher (serge-v) 2006-10-03 16:20:05
feel free to reopen when/if you reproduce and able to get the debugging information. Do also test the 1.4-beta.