"expire" for outgoing registrations not handled correctly?
Hi, It seems that I'm running into a timing issue with outgoing (gateway) registrations, which results in some milliseconds in that I can't send calls over that gateway. I have configured a gateway like this: <gateway name="duro"> <param name="username" value="XXXXXXX"/> <param name="from-domain" value="durosip.qsc.de"/> <param name="password" value="XXXXXXXXXXX"/> <param name="proxy" value="durosip.qsc.de"/> <param name="expire-seconds" value="120"/> <param name="register" value="true"/>^M <param name="register-transport" value="udp"/> <param name="retry-seconds" value="5"/> <param name="caller-id-in-from" value="true"/> </gateway>^M If I look at the "200 OK" messages for the SIP REGISTER packet, the server sends me an "Expires: 30", so FreeSwitch should re-REGISTER every 30 seconds. However, that's what happening: 2012-01-09 16:37:00.804865 [NOTICE] sofia_reg.c:407 Registering duro 2012-01-09 16:37:31.804880 [NOTICE] sofia_reg.c:407 Registering duro 2012-01-09 16:38:03.804894 [NOTICE] sofia_reg.c:407 Registering duro 2012-01-09 16:38:35.824877 [NOTICE] sofia_reg.c:407 Registering duro *2012-01-09 16:39:06.825090 [NOTICE] sofia_reg.c:407 Registering duro* 2012-01-09 16:39:39.824881 [NOTICE] sofia_reg.c:407 Registering duro You can see that it's *approximately* 30 seconds betwee registrations, but in fact every time it's just a little more than 30 secs. This alone makes me feel a little bit strange, since my registration might have been expired during this time window (and consequently, maybe I'm loosing incoming calls because of that). Even for outgoing calls, this seems to be an issue, let's take a look at the 16:39:06.825090 re-REGISTER. We can see that at 16:39:05 (no micro-seconds here) the gateway becomes "UNREGED": Content-Length: 542 Content-Type: text/event-plain Event-Subclass: sofia::gateway_state Event-Name: CUSTOM Core-UUID: 243269fe-d280-4f83-aca1-abb88f2ad258 FreeSWITCH-Hostname: lap597 FreeSWITCH-Switchname: lap597 FreeSWITCH-IPv4: 192.168.232.164 FreeSWITCH-IPv6: ::1 *Event-Date-Local: 2012-01-09 16:39:05* Event-Date-GMT: Mon, 09 Jan 2012 15:39:05 GMT Event-Date-Timestamp: 1326123545824882 Event-Calling-File: sofia_reg.c Event-Calling-Function: sofia_reg_fire_custom_gateway_state_event Event-Calling-Line-Number: 151 Gateway: duro State: UNREGED Ping-Status: UP But the new REGISTER is done a full second later (this is not just a display issue, I saw those messages scrolling by and there was just a second pause between them): Event-Subclass: sofia::gateway_state Event-Name: CUSTOM Core-UUID: 243269fe-d280-4f83-aca1-abb88f2ad258 FreeSWITCH-Hostname: lap597 FreeSWITCH-Switchname: lap597 FreeSWITCH-IPv4: 192.168.232.164 FreeSWITCH-IPv6: ::1 Event-Date-Local: 2012-01-09 16:39:06 *Event-Date-GMT: Mon, 09 Jan 2012 15:39:06 GMT* Event-Date-Timestamp: 1326123546825090 Event-Calling-File: sofia_reg.c Event-Calling-Function: sofia_reg_fire_custom_gateway_state_event Event-Calling-Line-Number: 151 Gateway: duro State: TRYING Ping-Status: DOWN Then, the gateway gets re-registered in a couple of milliseconds and everything is fine again. *It seems that this behaviour effectively creates a timespan of 1-2 seconds, where the gateway is not available for outgoing (and maybe also incoming) calls.* Does anyone of you know this issue? I wonder because this looks just to easy to be wrong in this fashion? Greetings, Roland
It might be because we only check for expiration every 30 seconds. update to latest GIT and I added a profile param: registration-thread-frequency The default is 30 so you can try setting it to 10 or 5 or something. 2012/1/9 Roland Hänel <roland@haenel.me>
Hi,
It seems that I'm running into a timing issue with outgoing (gateway) registrations, which results in some milliseconds in that I can't send calls over that gateway.
I have configured a gateway like this:
<gateway name="duro"> <param name="username" value="XXXXXXX"/> <param name="from-domain" value="durosip.qsc.de"/> <param name="password" value="XXXXXXXXXXX"/> <param name="proxy" value="durosip.qsc.de"/> <param name="expire-seconds" value="120"/> <param name="register" value="true"/>^M <param name="register-transport" value="udp"/> <param name="retry-seconds" value="5"/> <param name="caller-id-in-from" value="true"/> </gateway>^M
If I look at the "200 OK" messages for the SIP REGISTER packet, the server sends me an "Expires: 30", so FreeSwitch should re-REGISTER every 30 seconds.
However, that's what happening:
2012-01-09 16:37:00.804865 [NOTICE] sofia_reg.c:407 Registering duro 2012-01-09 16:37:31.804880 [NOTICE] sofia_reg.c:407 Registering duro 2012-01-09 16:38:03.804894 [NOTICE] sofia_reg.c:407 Registering duro 2012-01-09 16:38:35.824877 [NOTICE] sofia_reg.c:407 Registering duro *2012-01-09 16:39:06.825090 [NOTICE] sofia_reg.c:407 Registering duro* 2012-01-09 16:39:39.824881 [NOTICE] sofia_reg.c:407 Registering duro
You can see that it's *approximately* 30 seconds betwee registrations, but in fact every time it's just a little more than 30 secs. This alone makes me feel a little bit strange, since my registration might have been expired during this time window (and consequently, maybe I'm loosing incoming calls because of that).
Even for outgoing calls, this seems to be an issue, let's take a look at the 16:39:06.825090 re-REGISTER.
We can see that at 16:39:05 (no micro-seconds here) the gateway becomes "UNREGED":
Content-Length: 542 Content-Type: text/event-plain
Event-Subclass: sofia::gateway_state Event-Name: CUSTOM Core-UUID: 243269fe-d280-4f83-aca1-abb88f2ad258 FreeSWITCH-Hostname: lap597 FreeSWITCH-Switchname: lap597 FreeSWITCH-IPv4: 192.168.232.164 FreeSWITCH-IPv6: ::1 *Event-Date-Local: 2012-01-09 16:39:05* Event-Date-GMT: Mon, 09 Jan 2012 15:39:05 GMT Event-Date-Timestamp: 1326123545824882 Event-Calling-File: sofia_reg.c Event-Calling-Function: sofia_reg_fire_custom_gateway_state_event Event-Calling-Line-Number: 151 Gateway: duro State: UNREGED Ping-Status: UP
But the new REGISTER is done a full second later (this is not just a display issue, I saw those messages scrolling by and there was just a second pause between them):
Event-Subclass: sofia::gateway_state Event-Name: CUSTOM Core-UUID: 243269fe-d280-4f83-aca1-abb88f2ad258 FreeSWITCH-Hostname: lap597 FreeSWITCH-Switchname: lap597 FreeSWITCH-IPv4: 192.168.232.164 FreeSWITCH-IPv6: ::1 Event-Date-Local: 2012-01-09 16:39:06 *Event-Date-GMT: Mon, 09 Jan 2012 15:39:06 GMT* Event-Date-Timestamp: 1326123546825090 Event-Calling-File: sofia_reg.c Event-Calling-Function: sofia_reg_fire_custom_gateway_state_event Event-Calling-Line-Number: 151 Gateway: duro State: TRYING Ping-Status: DOWN
Then, the gateway gets re-registered in a couple of milliseconds and everything is fine again.
*It seems that this behaviour effectively creates a timespan of 1-2 seconds, where the gateway is not available for outgoing (and maybe also incoming) calls.*
Does anyone of you know this issue? I wonder because this looks just to easy to be wrong in this fashion?
Greetings, Roland
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
-- Anthony Minessale II FreeSWITCH http://www.freeswitch.org/ ClueCon http://www.cluecon.com/ Twitter: http://twitter.com/FreeSWITCH_wire AIM: anthm MSN:anthony_minessale@hotmail.com GTALK/JABBER/PAYPAL:anthony.minessale@gmail.com IRC: irc.freenode.net #freeswitch FreeSWITCH Developer Conference sip:888@conference.freeswitch.org googletalk:conf+888@conference.freeswitch.org pstn:+19193869900
Hello Anthony, Thanks. I have tested the registration-thread-frequency, but it seems this does not address the issue I'm having here. But the good news is: I just found the bug with the help of Alexandr Dubovikov... In sofia_reg.c, sofia_reg_check_gateway(...) it reads: if (gateway_ptr->freq >= 60) { gateway_ptr->expires = now + (gateway_ptr->freq - 15); } else { if (gateway_ptr->freq < 30 && gateway_ptr->freq >= 5) { gateway_ptr->expires = now + (gateway_ptr->freq - 5); } else { gateway_ptr->expires = now + (gateway_ptr->freq); } } this results in a re-REGISTER 15 seconds ahead of expiration if the register timer is more than 60 seconds. We are a 5 seconds ahead of expiration if the register timer is between 5 and 29 seconds. And the winner is... if the register timer is between 30 and 59 seconds, we have no "ahead". Obviously a bug, since the code is difficult to read with all those else conditions. I created a patch, verified that is works and attached it to this mail. Let me know if I need to do more (open an issue etc.) to make sure this patch gets applied... Thanks again, Roland 2012/1/10 Anthony Minessale <anthony.minessale@gmail.com>
It might be because we only check for expiration every 30 seconds.
update to latest GIT and I added a profile param: registration-thread-frequency
The default is 30 so you can try setting it to 10 or 5 or something.
2012/1/9 Roland Hänel <roland@haenel.me>
Hi,
It seems that I'm running into a timing issue with outgoing (gateway) registrations, which results in some milliseconds in that I can't send calls over that gateway.
I have configured a gateway like this:
<gateway name="duro"> <param name="username" value="XXXXXXX"/> <param name="from-domain" value="durosip.qsc.de"/> <param name="password" value="XXXXXXXXXXX"/> <param name="proxy" value="durosip.qsc.de"/> <param name="expire-seconds" value="120"/> <param name="register" value="true"/>^M <param name="register-transport" value="udp"/> <param name="retry-seconds" value="5"/> <param name="caller-id-in-from" value="true"/> </gateway>^M
If I look at the "200 OK" messages for the SIP REGISTER packet, the server sends me an "Expires: 30", so FreeSwitch should re-REGISTER every 30 seconds.
However, that's what happening:
2012-01-09 16:37:00.804865 [NOTICE] sofia_reg.c:407 Registering duro 2012-01-09 16:37:31.804880 [NOTICE] sofia_reg.c:407 Registering duro 2012-01-09 16:38:03.804894 [NOTICE] sofia_reg.c:407 Registering duro 2012-01-09 16:38:35.824877 [NOTICE] sofia_reg.c:407 Registering duro *2012-01-09 16:39:06.825090 [NOTICE] sofia_reg.c:407 Registering duro* 2012-01-09 16:39:39.824881 [NOTICE] sofia_reg.c:407 Registering duro
You can see that it's *approximately* 30 seconds betwee registrations, but in fact every time it's just a little more than 30 secs. This alone makes me feel a little bit strange, since my registration might have been expired during this time window (and consequently, maybe I'm loosing incoming calls because of that).
Even for outgoing calls, this seems to be an issue, let's take a look at the 16:39:06.825090 re-REGISTER.
We can see that at 16:39:05 (no micro-seconds here) the gateway becomes "UNREGED":
Content-Length: 542 Content-Type: text/event-plain
Event-Subclass: sofia::gateway_state Event-Name: CUSTOM Core-UUID: 243269fe-d280-4f83-aca1-abb88f2ad258 FreeSWITCH-Hostname: lap597 FreeSWITCH-Switchname: lap597 FreeSWITCH-IPv4: 192.168.232.164 FreeSWITCH-IPv6: ::1 *Event-Date-Local: 2012-01-09 16:39:05* Event-Date-GMT: Mon, 09 Jan 2012 15:39:05 GMT Event-Date-Timestamp: 1326123545824882 Event-Calling-File: sofia_reg.c Event-Calling-Function: sofia_reg_fire_custom_gateway_state_event Event-Calling-Line-Number: 151 Gateway: duro State: UNREGED Ping-Status: UP
But the new REGISTER is done a full second later (this is not just a display issue, I saw those messages scrolling by and there was just a second pause between them):
Event-Subclass: sofia::gateway_state Event-Name: CUSTOM Core-UUID: 243269fe-d280-4f83-aca1-abb88f2ad258 FreeSWITCH-Hostname: lap597 FreeSWITCH-Switchname: lap597 FreeSWITCH-IPv4: 192.168.232.164 FreeSWITCH-IPv6: ::1 Event-Date-Local: 2012-01-09 16:39:06 *Event-Date-GMT: Mon, 09 Jan 2012 15:39:06 GMT* Event-Date-Timestamp: 1326123546825090 Event-Calling-File: sofia_reg.c Event-Calling-Function: sofia_reg_fire_custom_gateway_state_event Event-Calling-Line-Number: 151 Gateway: duro State: TRYING Ping-Status: DOWN
Then, the gateway gets re-registered in a couple of milliseconds and everything is fine again.
*It seems that this behaviour effectively creates a timespan of 1-2 seconds, where the gateway is not available for outgoing (and maybe also incoming) calls.*
Does anyone of you know this issue? I wonder because this looks just to easy to be wrong in this fashion?
Greetings, Roland
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
-- Anthony Minessale II
FreeSWITCH http://www.freeswitch.org/ ClueCon http://www.cluecon.com/ Twitter: http://twitter.com/FreeSWITCH_wire
AIM: anthm MSN:anthony_minessale@hotmail.com GTALK/JABBER/PAYPAL:anthony.minessale@gmail.com IRC: irc.freenode.net #freeswitch
FreeSWITCH Developer Conference sip:888@conference.freeswitch.org googletalk:conf+888@conference.freeswitch.org pstn:+19193869900
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
-- Gruß, Roland
Sorry, it's me again :-| There is an additional issue to be fixed. Now that FreeSwitch re-REGISTERs soon enough, I'm still facing the problem that when the gateway state drops to REG_STATE_UNREGED, the status of the gateway is set to SOFIA_GATEWAY_DOWN. This is incorrect because it creates a short downtime for the gateway even if the re-REGISTER succeeds. The patch attached now corrects the status, that is, when the gateway re-REGISTERED, the status is not changed. Finally the registration will succeed (then, the status is forced UP) or fail (then, the status is forced DOWN). A gateway with continuous re-registrations now keeps the SOFIA_GATEWAY_UP status all the time, until a REGISTER fails. Greetings, Roland 2012/1/10 Roland Hänel <roland@haenel.me>
Hello Anthony,
Thanks. I have tested the registration-thread-frequency, but it seems this does not address the issue I'm having here.
But the good news is: I just found the bug with the help of Alexandr Dubovikov...
In sofia_reg.c, sofia_reg_check_gateway(...) it reads:
if (gateway_ptr->freq >= 60) { gateway_ptr->expires = now + (gateway_ptr->freq - 15); } else { if (gateway_ptr->freq < 30 && gateway_ptr->freq >= 5) { gateway_ptr->expires = now + (gateway_ptr->freq - 5); } else { gateway_ptr->expires = now + (gateway_ptr->freq); } }
this results in a re-REGISTER 15 seconds ahead of expiration if the register timer is more than 60 seconds. We are a 5 seconds ahead of expiration if the register timer is between 5 and 29 seconds. And the winner is... if the register timer is between 30 and 59 seconds, we have no "ahead". Obviously a bug, since the code is difficult to read with all those else conditions.
I created a patch, verified that is works and attached it to this mail. Let me know if I need to do more (open an issue etc.) to make sure this patch gets applied...
Thanks again, Roland
2012/1/10 Anthony Minessale <anthony.minessale@gmail.com>
It might be because we only check for expiration every 30 seconds.
update to latest GIT and I added a profile param: registration-thread-frequency
The default is 30 so you can try setting it to 10 or 5 or something.
2012/1/9 Roland Hänel <roland@haenel.me>
Hi,
It seems that I'm running into a timing issue with outgoing (gateway) registrations, which results in some milliseconds in that I can't send calls over that gateway.
I have configured a gateway like this:
<gateway name="duro"> <param name="username" value="XXXXXXX"/> <param name="from-domain" value="durosip.qsc.de"/> <param name="password" value="XXXXXXXXXXX"/> <param name="proxy" value="durosip.qsc.de"/> <param name="expire-seconds" value="120"/> <param name="register" value="true"/>^M <param name="register-transport" value="udp"/> <param name="retry-seconds" value="5"/> <param name="caller-id-in-from" value="true"/> </gateway>^M
If I look at the "200 OK" messages for the SIP REGISTER packet, the server sends me an "Expires: 30", so FreeSwitch should re-REGISTER every 30 seconds.
However, that's what happening:
2012-01-09 16:37:00.804865 [NOTICE] sofia_reg.c:407 Registering duro 2012-01-09 16:37:31.804880 [NOTICE] sofia_reg.c:407 Registering duro 2012-01-09 16:38:03.804894 [NOTICE] sofia_reg.c:407 Registering duro 2012-01-09 16:38:35.824877 [NOTICE] sofia_reg.c:407 Registering duro *2012-01-09 16:39:06.825090 [NOTICE] sofia_reg.c:407 Registering duro* 2012-01-09 16:39:39.824881 [NOTICE] sofia_reg.c:407 Registering duro
You can see that it's *approximately* 30 seconds betwee registrations, but in fact every time it's just a little more than 30 secs. This alone makes me feel a little bit strange, since my registration might have been expired during this time window (and consequently, maybe I'm loosing incoming calls because of that).
Even for outgoing calls, this seems to be an issue, let's take a look at the 16:39:06.825090 re-REGISTER.
We can see that at 16:39:05 (no micro-seconds here) the gateway becomes "UNREGED":
Content-Length: 542 Content-Type: text/event-plain
Event-Subclass: sofia::gateway_state Event-Name: CUSTOM Core-UUID: 243269fe-d280-4f83-aca1-abb88f2ad258 FreeSWITCH-Hostname: lap597 FreeSWITCH-Switchname: lap597 FreeSWITCH-IPv4: 192.168.232.164 FreeSWITCH-IPv6: ::1 *Event-Date-Local: 2012-01-09 16:39:05* Event-Date-GMT: Mon, 09 Jan 2012 15:39:05 GMT Event-Date-Timestamp: 1326123545824882 Event-Calling-File: sofia_reg.c Event-Calling-Function: sofia_reg_fire_custom_gateway_state_event Event-Calling-Line-Number: 151 Gateway: duro State: UNREGED Ping-Status: UP
But the new REGISTER is done a full second later (this is not just a display issue, I saw those messages scrolling by and there was just a second pause between them):
Event-Subclass: sofia::gateway_state Event-Name: CUSTOM Core-UUID: 243269fe-d280-4f83-aca1-abb88f2ad258 FreeSWITCH-Hostname: lap597 FreeSWITCH-Switchname: lap597 FreeSWITCH-IPv4: 192.168.232.164 FreeSWITCH-IPv6: ::1 Event-Date-Local: 2012-01-09 16:39:06 *Event-Date-GMT: Mon, 09 Jan 2012 15:39:06 GMT* Event-Date-Timestamp: 1326123546825090 Event-Calling-File: sofia_reg.c Event-Calling-Function: sofia_reg_fire_custom_gateway_state_event Event-Calling-Line-Number: 151 Gateway: duro State: TRYING Ping-Status: DOWN
Then, the gateway gets re-registered in a couple of milliseconds and everything is fine again.
*It seems that this behaviour effectively creates a timespan of 1-2 seconds, where the gateway is not available for outgoing (and maybe also incoming) calls.*
Does anyone of you know this issue? I wonder because this looks just to easy to be wrong in this fashion?
Greetings, Roland
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
-- Anthony Minessale II
FreeSWITCH http://www.freeswitch.org/ ClueCon http://www.cluecon.com/ Twitter: http://twitter.com/FreeSWITCH_wire
AIM: anthm MSN:anthony_minessale@hotmail.com GTALK/JABBER/PAYPAL:anthony.minessale@gmail.com IRC: irc.freenode.net #freeswitch
FreeSWITCH Developer Conference sip:888@conference.freeswitch.org googletalk:conf+888@conference.freeswitch.org pstn:+19193869900
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-users mailing list FreeSWITCH-users@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
-- Gruß, Roland
-- Gruß, Roland
participants (2)
-
Anthony Minessale
-
Roland Hänel