[Home]

Summary:ASTERISK-17636: Re-registration of SIP gateway sometimes occurs after the scheduled delay which causes gateway to see asterisk as unregistered
Reporter:Fred Peters (fpeters)Labels:
Date Opened:2011-04-03 03:39:48Date Closed:2018-01-02 08:44:27.000-0600
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Channels/chan_sip/Registration
Versions:1.6.2.15 Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) messages.txt
Description:Note: the version reported by asterisk is 1.6.2.5 (not found in the product version field of Mantis)

We have this problem on several asterisk installations.
We have some external SIP gateways we register to with a time-out of 120 seconds
Asterisk schedules a re-register every 105 second which is fine.
However, a few times a day, the re-registration occurs too late. This has the side effect of becoming invalid for the outside gateway point of view. On that outside gateway we have some specific rules in case asterisk is no more registered, so this problem causes missed calls if they occur within that "unregistered" period

Asterisk does not seems to be busy when the late re-registration occurs.

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

Below an extract of log which shows that re-register always occurs regularly excepted once where a comment has been inserted:

[Mar 31 08:01:22] NOTICE[1711] chan_sip.c:    -- Re-registration for  085519360@sip.3starsnet.com
[Mar 31 08:03:08] NOTICE[1711] chan_sip.c:    -- Re-registration for  085519360@sip.3starsnet.com
[Mar 31 08:04:53] NOTICE[1711] chan_sip.c:    -- Re-registration for  085519360@sip.3starsnet.com
[Mar 31 08:06:38] NOTICE[1711] chan_sip.c:    -- Re-registration for  085519360@sip.3starsnet.com
[Mar 31 08:08:24] NOTICE[1711] chan_sip.c:    -- Re-registration for  085519360@sip.3starsnet.com
[Mar 31 08:10:09] NOTICE[1711] chan_sip.c:    -- Re-registration for  085519360@sip.3starsnet.com
[Mar 31 08:11:54] NOTICE[1711] chan_sip.c:    -- Re-registration for  085519360@sip.3starsnet.com
[Mar 31 08:13:40] NOTICE[1711] chan_sip.c:    -- Re-registration for  085519360@sip.3starsnet.com
[Mar 31 08:15:25] NOTICE[1711] chan_sip.c:    -- Re-registration for  085519360@sip.3starsnet.com
[Mar 31 08:17:10] NOTICE[1711] chan_sip.c:    -- Re-registration for  085519360@sip.3starsnet.com
[Mar 31 08:18:56] NOTICE[1711] chan_sip.c:    -- Re-registration for  085519360@sip.3starsnet.com
[Mar 31 08:20:41] NOTICE[1711] chan_sip.c:    -- Re-registration for  085519360@sip.3starsnet.com
[Mar 31 08:22:26] NOTICE[1711] chan_sip.c:    -- Re-registration for  085519360@sip.3starsnet.com
[Mar 31 08:24:12] NOTICE[1711] chan_sip.c:    -- Re-registration for  085519360@sip.3starsnet.com
==> here we should have a re-register at 8:25:57
[Mar 31 08:26:38] NOTICE[1711] chan_sip.c:    -- Re-registration for  085519360@sip.3starsnet.com
[Mar 31 08:28:23] NOTICE[1711] chan_sip.c:    -- Re-registration for  085519360@sip.3starsnet.com
[Mar 31 08:30:08] NOTICE[1711] chan_sip.c:    -- Re-registration for  085519360@sip.3starsnet.com

Here is another extract of log file:
You an see at 00:23:49 that  re-registration is scheduled in 105 sec -> should
occur at 00:25:34, but it will only occurs at 00:26:41
SIP messages have been simplied to make it easier to read, but they were containing normal and successfull responses.

[Mar 31 00:23:49] VERBOSE[1711] chan_sip.c: --- (10 headers 0 lines) ---
[Mar 31 00:23:49] VERBOSE[1711] chan_sip.c: Scheduling destruction of SIP dialog '0eb640890787bd0910dc09b4613491f8@192.168.1.100' in 32000 ms (Method: REGISTER)
[Mar 31 00:23:49] NOTICE[1711] chan_sip.c: Outbound Registration: Expiry for sip.3starsnet.com is 120 sec (Scheduling reregistration in 105 s)
[Mar 31 00:24:21] VERBOSE[1711] chan_sip.c: Really destroying SIP dialog '0eb640890787bd0910dc09b4613491f8@192.168.1.100' Method: REGISTER
[Mar 31 00:24:42] VERBOSE[1711] chan_sip.c: Reliably Transmitting (no NAT) to 85.119.188.3:5060:
OPTIONS sip:sip.3starsnet.com SIP/2.0^M
Via: SIP/2.0/UDP 192.168.1.100:5060;branch=z9hG4bK5c214d56;rport
....

[Mar 31 00:24:42] VERBOSE[1711] chan_sip.c:.
<--- SIP read from UDP:85.119.188.3:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.100:5060;branch=z9hG4bK5c214d56;rport=64508
....

[Mar 31 00:24:42] VERBOSE[1711] chan_sip.c: --- (9 headers 0 lines) ---
[Mar 31 00:24:42] VERBOSE[1711] chan_sip.c: Really destroying SIP dialog '362d4deb7e5f5ed744b6f2074c3cb115@192.168.1.100' Method: OPTIONS
[Mar 31 00:25:42] VERBOSE[1711] chan_sip.c: Reliably Transmitting (no NAT) to 85.119.188.3:5060:
OPTIONS sip:sip.3starsnet.com SIP/2.0^M
Via: SIP/2.0/UDP 192.168.1.100:5060;branch=z9hG4bK4cf9581b;rport
....

[Mar 31 00:25:42] VERBOSE[1711] chan_sip.c:.
<--- SIP read from UDP:85.119.188.3:5060 --->
SIP/2.0 200 OK^M
Via: SIP/2.0/UDP 192.168.1.100:5060;branch=z9hG4bK4cf9581b;rport=64508
...

[Mar 31 00:25:42] VERBOSE[1711] chan_sip.c: --- (9 headers 0 lines) ---
[Mar 31 00:25:42] VERBOSE[1711] chan_sip.c: Really destroying SIP dialog '3378a1b9729be9593d552cad4045ed7b@192.168.1.100' Method: OPTIONS
[Mar 31 00:26:41] NOTICE[1711] chan_sip.c:    -- Re-registration for  085519360@sip.3starsnet.com
[Mar 31 00:26:41] VERBOSE[1711] dnsmgr.c:        > doing dnsmgr_lookup for 'sip.3starsnet.com'
[Mar 31 00:26:41] VERBOSE[1711] chan_sip.c: REGISTER 12 headers, 0 lines
[Mar 31 00:26:41] VERBOSE[1711] chan_sip.c: Reliably Transmitting (no NAT) to 85.119.188.3:5060:
REGISTER sip:sip.3starsnet.com SIP/2.0
Via: SIP/2.0/UDP 192.168.1.100:5060;branch=z9hG4bK64adec24;rport
...

Comments:By: Leif Madsen (lmadsen) 2011-04-05 16:22:26

You'll probably need to provide DEBUG level logging from the Asterisk console along with SIP history (as enabled from sip.conf) so that we can see what was happening. Please attach as a text file to the issue.
By: Fred Peters (fpeters) 2011-04-08 14:37:19

I attached a file with information. unfortunately it does not contain much more information than the one I placed in the message.
In fact asterisk is doing nothing at time the re-registration should take place.
If you look at the time asterisk is telling "Outbound Registration: Expiry for sip.3starsnet.com is 120 sec (Scheduling reregistration in 105 s)" and looking for just 105 secs after, then nothing happens asterisk is just idle, but the re-registration occurs somewhat later (and too late).
In the attached file, it occurs after 2 minutes and 3 seconds, so 18 seconds later than scheduled.
By: Fred Peters (fpeters) 2011-04-08 14:41:17

if you want more debug info, please tell me how to get it, I enabled in sip.conf:

sipdebug = yes
recordhistory=yes
dumphistory=yes

also, in logger.conf:

messages => notice,warning,error,verbose,debug

The attached file is an extract of messages file
By: Fred Peters (fpeters) 2011-04-12 09:59:54

Is there something else I can do to get some feedback on this problem ?
do you need more information ? are you able to simulate the problem ?
Thanks
By: Fred Peters (fpeters) 2011-04-24 09:08:29

This is still a blocking issue as it causes some calls to be missed.
Has nobody else this issue ?
By: Fred Peters (fpeters) 2011-04-28 15:53:20

We upgraded to 1.8.3.3 and still have the same issue
By: Joshua C. Colp (jcolp) 2017-12-19 06:58:38.125-0600

Are you still experiencing this under a current supported version of Asterisk?
By: Asterisk Team (asteriskteam) 2018-01-02 08:44:27.563-0600

Suspended due to lack of activity. This issue will be automatically re-opened if the reporter posts a comment. If you are not the reporter and would like this re-opened please create a new issue instead. If the new issue is related to this one a link will be created during the triage process. Further information on issue tracker usage can be found in the Asterisk Issue Guidlines [1].

[1] https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines