[OpenSIPS-Users] Registration Loss on opensips SBC

Bogdan-Andrei Iancu bogdan at opensips.org
Mon Feb 5 10:50:15 EST 2018 

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:
>
> Feb4 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
>
> Feb4 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
>
> Feb4 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
>
> Feb4 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
>
> Feb4 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
>
>
> Feb4 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
>
> Feb4 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
>
> Feb4 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
>
> Feb4 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
>
> Feb4 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
>
> Feb4 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
>
> Feb4 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
>
> Feb4 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 list
> Users at lists.opensips.org
> http://lists.opensips.org/cgi-bin/mailman/listinfo/users

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.opensips.org/pipermail/users/attachments/20180205/cd3f7e0a/attachment.html>

More information about the Users mailing list