Summary:	ASTERISK-07873: asterisk doesn't register anymore, sip show registry status show "Request Sent"
Reporter:	nettie (nettie)	Labels:
Date Opened:	2006-10-04 18:59:16	Date Closed:	2007-03-05 14:24:10.000-0600
Priority:	Major	Regression?	No
Status:	Closed/Complete	Components:	Channels/chan_sip/Registration
Versions:		Frequency of Occurrence
Related Issues:
Environment:		Attachments:	( 0) messages.txt ( 1) panciom_sipdebug.txt.zip ( 2) sipdebug.txt
Description:	I guys, I'm having some registration issues with asterisk and my voip carrier. As far as I know it doesnt look like a simple configuration issue but more like a bug. I'll do my best to describe the issue as best as I can, if anyone might be interested in hooking me up please dont hesitate to ask me more details. I'm running asterisk 1.2.12.1 -- I'm experiecing registration issues when my voip carrier asterisk server isnt reachable for a couple of minutes (unfortunately they're having huge problems lately). After a couple of retrys chan_sip registration hangs. When I log to the console and I do a "sip show registry" I see "Request Sent" as state for the related peer. The problem is that the request never times out and asterisk just stops trying register again. The only way I can force it to retry the registration is with "sip reload". After I issue that command asterisk registers perfectly. Looking at the log I definitely see that there's something wrong, I see a notice saying that sched.c is attempting to delete a nonexistent schedule entry and before that I noticed that there's also a warning saying that my URI is trying to register with a wrong password (voip carrier asterisk auth system down?) This happens to me every time my voip carrier server is not reachable or their authentication system is down, so it's pretty hard to me reproduce it. Thanx ****** ADDITIONAL INFORMATION ****** Oct  4 11:41:53 WARNING[14808] chan_sip.c: Forbidden - wrong password on authentication for REGISTER for 'blahblah' to 'sip.blah.com' Oct  4 12:48:11 NOTICE[14808] sched.c: Attempted to delete nonexistent schedule entry 817329!
Comments:	By: Serge Vecher (serge-v) 2006-10-05 08:24:06 As per bug guidelines, you need to attach a SIP debug trace illustrating the problem. Please do the following: 1) Prepare test environment (reduce the amount 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 sip debug 5) Save complete console log to file and _attach_ said file to the bug.  i.e. asterisk -Tvvvvvdddddgc | tee /tmp/sipdebug.txt By: Olle Johansson (oej) 2006-10-29 13:22:17.000-0600 Make sure that registerattempts=0 in your sip.conf. Try with that. By: David Daeschler (ddaeschl) 2006-10-31 09:15:29.000-0600 We have the same problem with a sip provider that uses the BroadWorks platform.  For whatever reason sometimes their server will begin telling asterisk that our usernames could not be found and issue a 404.  At this point asterisk gives up on the registration, which means we no longer recieve incoming calls, which costs us a lot of money.  I don't know why the BroadWorks/BroadSoft equipment is failing, but for us there doesn't appear to be any way around it besides writing a script that waits for the 404 and restarts sip some time later (hopefully when the broadsoft wakes up and realizes that we are valid users).  Is there a setting to force asterisk to retry registrations regardless of what the reason for failure is? An example of what happens in our logs.. Oct 31 01:55:02 WARNING[2249] chan_sip.c: Got 404 Not found on SIP register to service XXXXXXXXXX@telcove-in-XXXX, giving up ... 15 more lines of failure for all of our inbound regs ... THen when I do a sip show registry I see "Request Sent". By: Olle Johansson (oej) 2006-11-14 06:03:25.000-0600 Please follow the bug guidelines and upload a SIP debug of the whole transactions - see serge-v's note earlier. Thank you. By: Javi Lavandeira (ag0ny) 2006-11-16 03:07:34.000-0600 I have the same problem with Asterisk 1.2.13 and an iCom SR5200 VoIP gateway. I'll try to post a log file in a few minutes, as soon as it timeouts again. By: Javi Lavandeira (ag0ny) 2006-11-16 03:37:03.000-0600 I uploaded the log file from my server. I edited out several unrelated Zap lines. By: David Brazier (brazierd) 2006-11-16 17:42:03.000-0600 We have a similar issue with one of our providers.  Very occasionally, they reject our password on a REGISTER, and then Asterisk gives up registering, so we get no more incoming calls.  Worse, for no very good reason, they also subsequently prevent outbound calls, even though INVITEs are authenticated independently, of course.   We don't have SIP logs of these events, but I've shown extracts for the last two below.  In both cases, once we noticed, a reload fixed it, because Asterisk tried again to register and succeeded. So, my 2p worth is that these are faults in the provider rather than Asterisk, but Asterisk is being unforgiving by failing to try again when it gets a 403 repsonse.  Perhaps Asterisk should treat 403 (and perhaps 404 and 479) the same as a time out? There is also the possibility that there is a bug in the Asterisk handling of digest authentication that causes spordaic failures, but I doubt it. Oct 17 12:11:30 NOTICE[9026] chan_sip.c:    -- Re-registration for  01234567890@sip.voip-provider.blah Oct 17 12:11:30 WARNING[9026] chan_sip.c: Forbidden - wrong password on authentication for REGISTER for '01234567890' to 'sip.voip-provider.blah' Nov  2 20:37:30 NOTICE[9026] chan_sip.c:    -- Registration for '01234567890@sip.voip-provider.blah' timed out, trying again (Attempt #1) Nov  2 20:37:50 NOTICE[9026] chan_sip.c:    -- Registration for '01234567890@sip.voip-provider.blah' timed out, trying again (Attempt #2) Nov  2 20:37:52 NOTICE[9026] chan_sip.c: Peer 'voip-provider' is now UNREACHABLE!  Last qualify: 12 Nov  2 20:38:00 WARNING[9026] chan_sip.c: Forbidden - wrong password on authentication for REGISTER for '01234567890' to 'sip.voip-provider.blah' Nov  2 20:38:02 NOTICE[9026] chan_sip.c: Peer 'voip-provider' is now REACHABLE! (360ms / 2000ms) Nov  2 20:38:05 NOTICE[9026] sched.c: Attempted to delete nonexistent schedule entry 191753! Nov  2 20:38:05 WARNING[9026] chan_sip.c: Got 200 OK on REGISTER that isn't a register Nov  2 20:40:10 NOTICE[9026] chan_sip.c:    -- Registration for '01234567890@sip.voip-provider.blah' timed out, trying again (Attempt #2) Nov  2 20:40:22 WARNING[9026] chan_sip.c: Got 200 OK on REGISTER that isn't a register Cheers David By: Serge Vecher (serge-v) 2006-11-20 14:14:23.000-0600 ag0ny: you forgot to enable sip debug. Please review note 052589 and reproduce the debug as per posted instructions. Thanks. By: Olle Johansson (oej) 2006-11-30 15:04:59.000-0600 I do need a FULL sip debug file. Please upload one so I can see the SIP messages. Thanks. Thought: A CLI command and manager command to "restart" registrations that has failed. "sip registry restart" And maybe a setting to restart registrations automatically after a failure. Regfailuretimeout = 60, meaning that we restart registry items that failed after one hour By: Anthony LaMantia (alamantia) 2006-12-07 04:39:24.000-0600 nettie, have you experimented with oej's recommendations? By: John Backstrand (sandos) 2006-12-15 04:56:09.000-0600 This has happened for me on both 1.2 and with SVN/1.4 Branch. I have just added "registerattempts=0" to my sip.conf, although that is supposed to be default. Also, "Request sent" should mean we are in the middle of an request. When I noticed this for 1.4, it had gone almost 12 hours since the last request was sent. Is there no timeout between sending the request and receiving it? This should in my opinion trigger a re-request. I do not yet have a SIP debug, but I have a full log. (I checked my logs, and this is what happend with the last registration: [Dec 15 00:10:45] WARNING[30642] chan_sip.c: Got 404 Not found on SIP register to service xxxxxxxx@ipkund2.rixtelecom.se, giving up I will tell my VOIP-provider. If they dont want/cant fix this on their end, I will probably add a "hack" to asterisk to retry even after 404s. Would this be at all a candidate for inclusion? Also, asterisk dont seem to honor any retry-after value for getting a 404 on REGISTER? I dont think my provider uses this anyway, but still...) By: Mirko (panciom) 2007-01-12 15:20:56.000-0600 Thank you to all. I'm experiencing the same problem. I'm running Asterisk 1.2.6 without any patch. In this moment my asterisk is locked with "request sent". In this situation i can make outgoing call but incoming call never arrives. The other side of registration is my company's asterisk. I have already take the log to a file but without the debug option (tried some time ago but too much log). I send this log and for the next time i will write here i will upload the log with verbose debug option. Registerattemps was set to 10000 now to 0. Some info about the configuration: The asterisk (at home) is connected with an adsl with dynamic public IP. On the other side an asterisk with ip 10.0.0.7 rear a FW (NAT inside) with the public static ip sip.yyy.it. On January 11 the adsl goes down near 18:20 (i see on a mrtg graph). You see on the log that asterisk try to register on "Jan 11 18:31:59 WARNING[1359]". My ADSL goes up "Jan 11 19:20:41" read on the pppd logs. On the log you see a xxxxxx@192.168.0.1. On the linux-box at my home this IP never appear on the entire linux partition and i don't know where to find it. I hope this info can help you all. I'm here and i will follow the thread. If you need more info or sshing my asterisk... but for this i have to "know" a little the person :D. Bye to all. Panciom PS: sorry for my english! By: Serge Vecher (serge-v) 2007-01-15 09:21:26.000-0600 As requested, the debug log needs to be from the latest Asterisk release, which is 1.2.14 -- 1.2.6 is too old. Somebody needs to produce a useful debug log for this issue as per note 0052589. By: Mirko (panciom) 2007-01-17 10:12:19.000-0600 Mr. serge-v, i have installed asterisk 1.4.0 (the latest version i have found). I have put on logger.conf: vdebug => notice,warning,error,debug,verbose I have execute on CLI the following command: set debug 4 set verbose 4 sip debug If this procedure is not ok for debug tell me. I will follow exactly your instruction. I prefer this method for administrative purpose. I will send the vdebug log when the problem will appear. Thank you very much for your patience and work. Best Regards Panciom By: Serge Vecher (serge-v) 2007-01-19 13:36:18.000-0600 panciom, the problem is that not everything is written to a vdebug file -- just compare the file with console output as per note 52589 and you will see the difference. By: Mirko (panciom) 2007-02-07 08:18:03.000-0600 Thank you for the patience. I have uploaded the file as per note 52589. At Feb 1 18:32:03 (approx.) i have make a "sip reload" because the "request sent" appear. I can represent the "bug" when i want. I have just to download some big files at the maximum speed of my adsl blocking the comunication from my machine to asterisk at work. I hope this is useful. If something is missing write me. Thank you to all. Panciom PS: Log File Info ----------------- My LAN: 192.168.1.0/24 Default GW: 192.168.1.1 (gw.pancio.lan). On this machine (gw.pancio.lan) i have installed a bind (with forward and reverse resolution), asterisk 1.4.0 and a PCI ADSL modem (ppp0->88.149.213.210 and eth0->192.168.1.1) Registration that show "Request sent": Name: sip.mycompany.it IP: my_company_asterisk_ip My Asterisk 1.4.0 Dynamic Public IP: 88.149.213.210 By: Olle Johansson (oej) 2007-02-11 12:23:47.000-0600 please try latest 1.4 from subversion. I've fixed a bug in regards to outbound registrations in there, so make sure you test that version. By: Mirko (panciom) 2007-02-14 11:26:46.000-0600 "please try latest 1.4 from subversion." Sorry Oej... but i don't where to find info to try subversion. If you give me some more info i will try. Thank you very much Panciom By: Serge Vecher (serge-v) 2007-02-14 13:17:03.000-0600 > svn co http://svn.digium.com/svn/asterisk/branches/1.4 asterisk > svn co http://svn.digium.com/svn/zaptel/branches/1.4 zaptel > svn co http://svn.digium.com/svn/libpri/branches/1.2 libpri By: Serge Vecher (serge-v) 2007-03-05 14:24:09.000-0600 no response from anyone for over two weeks. If this issue is still present in 1.4.1, please reopen with a new sip debug log. Thanks.