[OpenSIPS-Users] Registration Loss on opensips SBC

Tue Feb 6 03:30:18 EST 2018

Thanks for lead Bogdan we will look into it.

Do you also have any idea why the t_relay was blocking for so long?

Royee

On Mon, Feb 5, 2018 at 7:23 PM Bogdan-Andrei Iancu <bogdan at opensips.org>
wrote:

> Hi Royee,
>
> I don't think it is related to xmlrpc - there are separate connection,
> separate processes for this.
>
> I would rather suspect the event routes - the event is in-line handled in
> usrloc, so the save() will cover the delivery/handling of the contact
> related events. And if you do something time consuming in
> event_route[E_UL_CONTACT_INSERT] lets say, this will reflect as processing
> time for the save() function.
>
> Regards,
>
> Bogdan-Andrei Iancu
>
> OpenSIPS Founder and Developer
>   http://www.opensips-solutions.com
> OpenSIPS Summit 2018
>   http://www.opensips.org/events/Summit-2018Amsterdam
>
> On 02/05/2018 06:44 PM, Royee Tichauer wrote:
>
> Bogdan,
>
> Not sure I follow about breaking each function. What do you mean by
> 'actual internal save()'?
>
> DB insert is not used.
>
> We use:
>
> event_route[E_UL_CONTACT_UPDATE]
>
> event_route[E_UL_CONTACT_DELETE]
>
> event_route[E_UL_CONTACT_INSERT]
>
> btw, we also use the mi_xmlrpc_ng constantly for monitoring if that might
> have something to do with it (I saw a comment on opensips 1.6 that there
> was an opensips blocking issue in some cases).
>
> Royee
>
>
>
> On Mon, Feb 5, 2018 at 6:34 PM Bogdan-Andrei Iancu <bogdan at opensips.org>
> wrote:
>
>> Hi Royee,
>>
>> Well, you need to break for each function the possible types of actions.
>> Like for save():
>>     - actual internal save()
>>     - DB insert  if realtime mode used
>>     - potential events triggering - do you use any usrloc related events ?
>>
>> Regards,
>>
>>
>> Bogdan-Andrei Iancu
>>
>> OpenSIPS Founder and Developer
>>   http://www.opensips-solutions.com
>> OpenSIPS Summit 2018
>>   http://www.opensips.org/events/Summit-2018Amsterdam
>>
>> On 02/05/2018 06:20 PM, Royee Tichauer wrote:
>>
>> Hi Bogdan, as the logs show:
>>
>> save - 8912725us
>> t_relay - 5355333us
>>
>> Let me know if you have any ideas,
>> Thanks,
>> Royee
>>
>>
>>
>>
>> On Mon, Feb 5, 2018 at 5:50 PM Bogdan-Andrei Iancu <bogdan at opensips.org>
>> wrote:
>>
>>> Hi Royee,
>>>
>>> what are the time values reported for 't_relay' and 'save' ? the 50ms
>>> threashold may not be so relevant for explaining delays of seconds.
>>>
>>> Best regards,
>>>
>>> Bogdan-Andrei Iancu
>>>
>>> OpenSIPS Founder and Developer
>>>   http://www.opensips-solutions.com
>>> OpenSIPS Summit 2018
>>>   http://www.opensips.org/events/Summit-2018Amsterdam
>>>
>>> On 02/05/2018 02:09 PM, Royee Tichauer via Users wrote:
>>>
>>> Hi,
>>>
>>> We are using opensips 2.1 as an SBC component and we see that we have
>>> loss of registrations happening once in a while. When we captured SIP we
>>> saw that some messages are being delayed by a couple of seconds. We enabled
>>> 'exec_execute_message=50000' and saw in the logs that opensips core methods
>>> like 't_realy' and 'save' . I looked at SAR during this time and there are
>>> no indications of CPU running high during this time.
>>>
>>> Can you help me figure out this issue?
>>>
>>> Thanks,
>>> Royee
>>>
>>> Logs:
>>>
>>> Feb  4 17:07:23 sbc.company.com <http://amz1vpsbc2.amz1.vocalocity.com/>
>>>  /usr/sbin/opensips[29827]: WARNING:core:log_expiry: threshold exceeded
>>> : msg processing took too long - 8912776 us.Source : SIP/2.0 200
>>> OK#015#012Via: SIP/2.0/UDP
>>> <ip>5060;received=<ip>;rport=5060;branch=z9hG4bK7eec.23d21053.0#015#012Via:
>>> SIP/2.0/UDP
>>> <ip>:5060;rport=5060;received=<ip>;branch=z9hG4bK2715962793#015#012From: ""
>>> <sip:<sip_id>@<account>.company.com:5060
>>> <http://sip:VH2677991@sip-190913.accounts.vocalocity.com:5060/>>;tag=646749010#015#012To:
>>> "###" <sip:#####@sip-#####.accounts.COMPANY.com:5060
>>> <http://sip:VH2677991@sip-190913.accounts.vocalocity.com:5060/>
>>> >;tag=8b4547f60a700f827fe775c80b65be1b.efed#015#012Call-ID:
>>> 0_2258842442@<ip>#015#012CSeq
>>> <http://0_2258842442@192.168.0.3/#015%23012CSeq>: 3575
>>> REGISTER#015#012Contact: <sip:######@<ip>:5060
>>> <http://sip:VH2677991@97.96.230.47:5060/>>;expires=45;received="sip:
>>> <ip>:5060 <http://52.7.62.159:5060/>"#015#012Server:
>>> Vonage#015#012Content-Length: 0#015#012#015#012
>>>
>>> Feb  4 17:07:23 sbc.amz1.company.com
>>> <http://amz1vpsbc2.amz1.vocalocity.com/> /usr/sbin/opensips[29827]:
>>> WARNING:core:log_expiry: #1 is a module action : save - 8912725us -
>>> line 914
>>>
>>> Feb  4 17:07:23 sbc.amz1.company.com
>>> <http://amz1vpsbc2.amz1.vocalocity.com/> /usr/sbin/opensips[29827]:
>>> WARNING:core:log_expiry: #2 is a core action : 80 - 17us - line 1103
>>>
>>> Feb  4 17:07:23 sbc.amz1.company.com
>>> <http://amz1vpsbc2.amz1.vocalocity.com/> /usr/sbin/opensips[29827]:
>>> WARNING:core:log_expiry: #3 is a core action : 72 - 5us - line 887
>>>
>>> Feb  4 17:07:23 sbc.amz1.company.com
>>> <http://amz1vpsbc2.amz1.vocalocity.com/> /usr/sbin/opensips[29820]:
>>> WARNING:core:log_expiry: threshold exceeded : msg processing took too
>>> long - 5355695 us.Source : REGISTER sip:####.accounts.company.com:5060
>>> <http://sip-190913.accounts.vocalocity.com:5060/> SIP/2.0#015#012Via:
>>> SIP/2.0/UDP <ip>:5060;branch=z9hG4bK2715962793#015#012From: "###" <
>>> sip:#####@sip-####.accounts.company.com:5060
>>> <http://sip:VH2677991@sip-190913.accounts.vocalocity.com:5060/>>;tag=646749010#015#012To:
>>> "####" <sip:####@sip-#####.accounts.company.com:5060
>>> <http://sip:VH2677991@sip-190913.accounts.vocalocity.com:5060/>
>>> >#015#012Call-ID: 0_2258842442@######015#012CSeq
>>> <http://0_2258842442@192.168.0.3/#015%23012CSeq>: 3575
>>> REGISTER#015#012Contact: <####@<ip>:5060
>>> <http://sip:VH2677991@97.96.230.47:5060/>>#015#012Authorization: Digest
>>> username="####", realm="####.accounts.company.com
>>> <http://sip-190913.accounts.vocalocity.com/>",
>>> nonce="5a773de000000b19dc7d21205f1edfda504fac90296b04fb", uri="sip:
>>> sip-#######.accounts.company.com:5060
>>> <http://sip-190913.accounts.vocalocity.com:5060/>",
>>> response="df8d6cbfd178a36913a1464920da3f06", algorithm=MD5#015#012Allow:
>>> INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER,
>>> SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE#015#012Max-Forwards:
>>> 69#015#012User-Agent: #########015#012Expires: 3600#015#012Allow-Events:
>>> talk,hold,conference,refer,check-sync#015#012Content-Length:
>>> 0#015#012#015#012
>>>
>>>
>>> Feb  4 17:07:23 sbc.amz1.company.com
>>> <http://amz1vpsbc2.amz1.vocalocity.com/>  /usr/sbin/opensips[29827]:
>>> WARNING:core:log_expiry: #4 is a core action : 72 - 5us - line 1086
>>>
>>> Feb  4 17:07:23 sbc.amz1.company.com
>>> <http://amz1vpsbc2.amz1.vocalocity.com/>  /usr/sbin/opensips[29820]:
>>> WARNING:core:log_expiry: #1 is a module action : t_relay - 5355333us -
>>> line 465
>>>
>>> Feb  4 17:07:23 sbc.amz1.company.com
>>> <http://amz1vpsbc2.amz1.vocalocity.com/>  /usr/sbin/opensips[29827]:
>>> WARNING:core:log_expiry: #5 is a module action : ds_is_in_list - 4us -
>>> line 943
>>>
>>> Feb  4 17:07:23 sbc.amz1.company.com
>>> <http://amz1vpsbc2.amz1.vocalocity.com/>  /usr/sbin/opensips[29817]:
>>> WARNING:core:log_expiry: #1 is a module action : t_relay - 7375370us -
>>> line 465
>>>
>>> Feb  4 17:07:23 sbc.amz1.company.com
>>> <http://amz1vpsbc2.amz1.vocalocity.com/>  /usr/sbin/opensips[29820]:
>>> WARNING:core:log_expiry: #2 is a core action : 78 - 105us - line 604
>>>
>>> Feb  4 17:07:23 sbc.amz1.company.com
>>> <http://amz1vpsbc2.amz1.vocalocity.com/>  /usr/sbin/opensips[29817]:
>>> WARNING:core:log_expiry: #2 is a core action : 78 - 100us - line 604
>>>
>>> Feb  4 17:07:23 sbc.amz1.company.com
>>> <http://amz1vpsbc2.amz1.vocalocity.com/>  /usr/sbin/opensips[29820]:
>>> WARNING:core:log_expiry: #3 is a core action : 78 - 99us - line 635
>>>
>>> Feb  4 17:07:23 sbc.amz1.company.com
>>> <http://amz1vpsbc2.amz1.vocalocity.com/>  /usr/sbin/opensips[29817]:
>>> WARNING:core:log_expiry: #3 is a core action : 78 - 98us - line 635
>>>
>>>
>>> _______________________________________________
>>> Users mailing listUsers at lists.opensips.orghttp://lists.opensips.org/cgi-bin/mailman/listinfo/users
>>>
>>>
>>>
>>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.opensips.org/pipermail/users/attachments/20180206/3699fbcf/attachment-0001.html>